627644 - sqlite3_trace logging is pathologically bad news for FTS3 users on debug builds

Status: RESOLVED WORKSFORME

(Toolkit :: Storage, enhancement)

Description

[Andrew Sutherland [:asuth] (he/him)]

Attachment: sucks to be someone who knows how to dynamically change log levels v1

I posted the following to the sqlite-users, list.  Here's a link in case there's a follow-up or anything:
http://www.mail-archive.com/[e-mail]/msg58266.html

And here's the body, enclosing in equals signs:
===========================================================================
In our Mozilla debug builds we use sqlite3_trace to expose the SQL 
statements that are invoked via our PR_LOG logging subsystem.  This 
usually works out well but the trace also catches FTS3's statements in 
its net.  During a segment merge, a segment in a Thunderbird FTS3 table 
can easily be >100k.

Unfortunately, the calls to stringify the BLOB end up growing the string 
"%02x" character by "%02x" character, and sqlite3StrAccumAppend grows 
its allocation size linearly and without using realloc.  This results in 
a tremendous number of calls to the allocator and a lot of memory 
traffic (both copying and memsetting).

While this is definitely one of those "well, don't do that" cases, I 
think it would be beneficial if one or more of the following were to 
occur, if only because it would be nice to not have to turn 
sqlite3_trace off on any connection that uses FTS3.

1) Cause FTS3 statements to not generate OP_Trace codes or to ignore 
them during evaluation.
2) Use realloc in sqlite3StrAccumAppend so the memory allocator has a 
fighting chance.  (With the large segment sizes at play, the mozilla 
jemalloc, for example, ends up unmapping things at least some of the time.)
3) Use a more efficient BLOB stringification routine.
4) Allow not stringifying BLOBs at all.
5) Place an upper bound or allow the sqlite3_trace invocation to place 
an upper bound on how large the SQL string can grow.

It's very survivable if none of the above ever happen, too.

Here's a snippet of an unhappy stack using the 3.7.4 amalgamation in the 
off-chance it helps provide better context:
#7  sqlite3Malloc (n=264183) at sqlite3/src/sqlite3.c:17763
#8  sqlite3DbMallocRaw (db=ptr, n=264183) at sqlite3.c:18088
#9  sqlite3StrAccumAppend (p=ptr, z=ptr, N=2) at sqlite3.c:19002
#10 sqlite3VXPrintf (pAccum=ptr, useExtended=1, fmt=ptr "x", 
ap=0x7fcaba7fc8e0) at sqlite3.c:18952
#11 sqlite3XPrintf (p=ptr, zFormat=ptr "%02x") at sqlite3.c:19241
#12 sqlite3VdbeExpandSql (p=ptr, zRawSql=ptr ")") at sqlite3.c:59748
#13 sqlite3VdbeExec (p=0x7fcaac70c5d8) at sqlite3.c:66203
#14 sqlite3Step (p=ptr) at sqlite3.c:58704
#15 sqlite3_step (pStmt=ptr) at sqlite3.c:58768
#16 fts3WriteSegment (p=ptr, iBlock=ptr, z=ptr "", n=166139) at 
sqlite3.c:115871
===========================================================================

We automatically activate sqlite3_trace on all debug builds in Connection::initialize regardless of the actual state of logging.  While it would be preferable if we could only activate sqlite3_trace if logging is actually activated, it is within the power of native in-tree consumers to safely, if evilly, cast mozIStorageConnection to Connection, gain access to the sqlite3* instance and then just turn the logging off for themselves.  (I have a patch for Thunderbird to do this, if needed.)

I propose the following:

1) Spin off a bug wherein we use PR_LOG_TEST to decide whether to tell sqlite3_trace to turn on in the first place.  I am attaching the patch that we would associate with that bug to this bug in the off-chance a braver person than I is willing to fight the good fight required to land this on mozilla-central in the near future.

2) Leave this bug around as a warning to others until something happens upstream that stops sqlite3_trace from being dangerous to FTS3 users on debug builds.

Comment 1

[Andrew Sutherland [:asuth] (he/him)]

Attachment: the thunderbird nuclear option v1

Depending on the timeline of resolving this in mozilla-central, this is the comm-central solution for Thunderbird.  I will spin this off into its own bug if/as needed.

Comment 2

[Seth Spitzer]

Andrew,  see also:

http://www.sqlite.org/cvstrac/tktview?tn=4009,39
http://www.mail-archive.com/[e-mail]/msg47219.html

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

The sqlite peeps have indicated that they will address the problem by:

- Optimizing the memory allocation code.

- Making sqlite3_trace provide the original SQL in comment for for nested queries so tracing can still understand what is going on, but without silly output.  (And also allowing the trace output to be replayed to a SQLite shell; the FTS nested queries are side-effects that you would never want to explicitly issue.)

This could happen for 3.7.5; given that this only affects debugging modes and we have acceptable means of working around the problem with minor patches, I expressed this is not a high priority from our perspective, but we would still appreciate the changes.

I would suggest the course of this bug continue as I proposed above.  Maybe modify mozStorage on a spin-off bug, maybe patch Thunderbird, close this one when we land a SQLite release on trunk that has the friendlier sqlite3 behaviour for nested queries.

Comment 4

[Andrew Sutherland [:asuth] (he/him)]

The SQLite people landed the changes which should show up in 3.7.5:

http://www.sqlite.org/src/info/380f61df07
http://www.sqlite.org/src/info/a764915b87

Comment 5

[Marco Bonardo [:mak]]

sounds like this has been solved with the 3.7.5 upgrade...