SQLite Forum

Debugging opcodes in vdbe.c
Dan Kennedy (dan) on 2020-09-22 13:40:24:

> Probably just buffering. Try:
>    fprintf(stdout, "format", ...);
>    fflush(stdout);

Yes you were right. The buffering has some very unhelpful effects during debugging, differing with the kinds of redirection and number of processes involved and giving the wrong impression with timing, as detailed at the end of this posting. I was additionally confused because plain unbuffered printfs exist in SQLite source code and I assumed that meant they would work, but they exhibit the same buffering weirdness.

That means the best advice currently for adding debugging statements to SQLite is:

1. add fflush to any printf statements like you said, or
2. switch on -DDEBUG_SQLITE and use printf.c/sqlite3DebugPrintf(), which has fflush and other good features already

There are a bit over 100 plain printfs in SQLite, most of them within <code>#define DEBUG_SQLITE</code> blocks. So presumably these should all be changed to sqlite3DebugPrintf(). That function doesn't just flush the buffer, it does other things including address a portability problem. Just generally it seems good for all debugging to go through a single choke point where it can be tee-d to a file or whatever else is needed during debugging.

It would also be helpful if sqlite3DebugPrintf() was available in non-SQLITE_DEBUG mode for quick and specific debugging. Would it cause much pain to remove the SQLITE_DEBUG around that function?

As to the confusing behaviour around buffered printfs (and thanks to Uilebheist for help with the testing here):

* while stdout buffering can cause printfs to be emitted at unexpected places they will however definitely be printed. It's just easy to miss the odd line if you have switched on a large amount of output, especially in 'make test'.
* because of buffering, the results will differ between runs using '>' shell redirection and with '| tee', which also differ between running 'make test' and in directly running the sqlite binary. 
* stdio is always flushed by the OS when a process exits. These different ways of running SQLite introduce different exit events, which changes when the printfs are displayed. 
* to add to the confusion, the 'script' command flushes the line buffer so that the printfs happen exactly when expected, so running the above tests under script can make the problem go away altogether.

Things that will not work to fix the problem:

* Making stdout unbuffered with setbuf(stdout, NULL), because that has interactions with redirections too.
* Using stderr instead of stdout. POSIX requires that stderr be unbuffered so that's great, but that doesn't change the fact that SQLite has unbuffered printfs, and it works differently in redirections.
* suspecting 'make test' - no, TCL does not grab the terminal, make test is innocent :-)