SQLite Forum

Debugging opcodes in vdbe.c

Debugging opcodes in vdbe.c

(1) By Dan Shearer (danshearer) on 2020-09-22 12:06:48 [link] [source]

I'd like to develop a process for examining what functions call and are called by a particular OpCode. To do this I need a reliable way of adding debug statements, and I have found some surprises in that.

The example I picked is the opcode IsSmaller.

From code inspection using grep and less, IsSmaller appears to only be triggered by "PRAGMA optimize", which in turn is somewhat exercised by the script test/busy.test. I used various debugging techniques to learn about how IsSmaller is used:

  1. I compiled with and without -DSQLITE_DEBUG
  2. I added some printfs to the implementation of IsSmaller in vdbe.c
  3. I made these printfs inside and outside #ifdef SQLITE_DEBUG
  4. I added PRAGMA vdbe_trace=ON/OFF at the beginning and end of busy.test
  5. I tried turning on debug mode for PRAGMA optimize with mask=0x0001
  6. Instead of printfs in vdbe.c, I appended debugging statements to a file
  7. I tried running the sqlite commandline as well as make test to trigger my debug statements inside IsSmaller

Note: When editing vdbe.c, it is important to strictly respect formatting because the whole C file including comments is parsed to generate code before the C compiler sees it.

Fundamental question: why does a printf statement inside an opcode seem to only sometimes work? Appending to a file always works, which is how I can compare. It is possible there are so many moving parts that I just got confused.

A subquestion: does the make test infrastructure capture and process stdout before resending it to stdout?

Opening and appending to a file does work reliably, which is how I know there are exactly 8 invocations of IsSmaller caused by operations in make test. Sometimes the printfs agree with this, and sometimes they don't appear at all. At least once only a few of the printfs are displayed.

I thought maybe vdbe_trace was the answer, but fifty thousand debug lines later, I began to see that ad-hoc printf's have some advantages. On the hand, when using vdbe_trace, printfs always seem to work, whether inside make test or not.

(As expected, adding r in front of the n at the end of printf statements makes no difference but I did try.)

I don't think I'm the first to have noticed strange behaviour of this kind. I'd like to work out what it is and document it.



(2) By Dan Kennedy (dan) on 2020-09-22 13:40:24 in reply to 1 [source]

Probably just buffering. Try:

    fprintf(stdout, "format", ...);

[make test] doesn't do anything special with stdout of the executable. That I can think of, anyway...


(3) By Dan Shearer (danshearer) on 2020-09-22 18:42:58 in reply to 2 [link] [source]

In reply to Dan Kennedy (dan) on 2020-09-22 13:40:24:

That does make a difference, and I'm re-running my tests to be sure.

Assuming it does, there is a handful of printfs in vdbe*c that would seem to be similarly vulnerable to OS and other local variability.



(4) By Dan Shearer (danshearer) on 2020-09-25 08:10:43 in reply to 2 [link] [source]

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 #define DEBUG_SQLITE 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 :-)


(5) By Rowan Worth (sqweek) on 2020-09-25 08:58:49 in reply to 4 [link] [source]

Note you can also use the stdbuf tool in the shell to control stdio buffering within pipelines. The default behaviour depends on the tool, but for those which use glibc's stdio (FILE* and friends) it goes like this:

(a) if stdout is a tty, then output is buffered on a line-by-line basis (b) otherwise, output is buffered in fixed size chunks (IIRC the default is 1MB)

Which is why things can change when you tack | tee on the end of a command vs. having it output straight to the console. In this case you can prepend stdbuf -oL to whichever command is buffering to force stdout back to line buffered.

For a quick demo, start with a simple loop emitting one message per second and log timestamps when they are received:

$ for i in $(seq 1 3); do echo $i; sleep 1; done | awk '{print strftime("%F %T"), $1}'
2020-09-25 16:48:13 1
2020-09-25 16:48:14 2
2020-09-25 16:48:15 3

Now add a filter for odd numbers: sed -n '/[13579]$/p':

$ for i in $(seq 1 3); do echo $i; sleep 1; done | sed -n '/[13579]$/p' | awk '{print strftime("%F %T"), $1}'
2020-09-25 16:49:18 1
2020-09-25 16:49:18 3

Note nothing is printed for three seconds, and then both lines have the same timestamp. sed is buffering the output -- rude. stdbuf to the rescue:

$ for i in $(seq 1 3); do echo $i; sleep 1; done | stdbuf -oL sed -n '/[13579]$/p' | awk '{print strftime("%F %T"), $1}'
2020-09-25 16:50:10 1
2020-09-25 16:50:12 3

It's done this way because block buffering enables better pipeline performance compared to line buffering, but it's such a subtle thing to have tools changing behaviour like this that I feel GNU userspace would be simplified so much if block buffering was strictly opt-in...

(6) By Dan Shearer (danshearer) on 2020-09-25 09:28:46 in reply to 5 [link] [source]

Rowan Worth (sqweek) wrote on 2020-09-25 08:58:49:

The default behaviour depends on the tool, but for those which use glibc's stdio (FILE* and friends) it goes like this:

That's really helpful and I can see I'll be using stdbuf. I didn't know it existed, and I see it's in GNU coreutils and has been re-implemented for BSD so that's most of the platforms I use.

It isn't a solution for all the platforms SQLite supports though, and it does require some extra knowledge, which is why I feel that using sqlite3DebugPrintf() consistently throughout will improve SQLite.


(7.1) By Dan Shearer (danshearer) on 2020-09-25 09:32:50 edited from 7.0 in reply to 5 [link] [source]