Sunday, April 2, 2017

Published the recorder project on GitHub, a lock-free, real-time flight recorder for your C or C++ programs

Instrumentation that is always there when you need it

The flight recorder is designed to help you debug complex, real-time, multi-CPU programs. It lets you instrument their execution with non-intrusive `printf`-like *record statements*, that capture what is happening in your program. These record statements are very inexpensive (about 80-100ns on a modern x86), so you can leave them in your code all the time, even for optimized code.

Then, when something bad happens or from within a debugger, you can *dump the recorder*, which gives you a very detailed account of recent events, helping you figure out how you came there. The recorder dump also contains highly detailed ordering and timing information, which can be very precious in multi-CPU systems.

Multiple recorders can be active simultaneously, for example to capture events from different subsystems. When a recorder dump occurs, events from different recorders are sorted so that you get a picture of how the systems interacted. Different recorders can have different size and different refresh rates, but a very fast recorder will not push away data from a slower one. This ensure you can record important, but slow, events, as well as much more frequent ones.

Here is what a recorder dump can look like:

0 [0.000000:0x10d463170] Main: Launching 16 recorder threads
1 [0.000019:0x10d4631bb] Main: Starting speed test for 10s with 16 threads
2179 [0.000235:0x10d46320c] Main: Recorder testing in progress, please wait about 10s
104892175 [10.001407:0x10d463277] Main: Recorder testing completed, 104892165 iterations
104892207 [10.001410:0x10d4630bc] SpeedTest: Recording 104892205
104892208 [10.001411:0x10d4630bc] SpeedTest: Recording 104892206
104892233 [10.001413:0x10d4632ff] Pauses: Waiting for recorder threads to stop, 16 remaining
104892234 [10.001432:0x10d463368] Pauses: Pausing 2401.618us
104892235 [10.001437:0x10d4630bc] SpeedTest: Recording 104892231
104892238 [10.004529:0x10d463393] Main: All threads have stopped.
104892239 [10.004573:0x10d463422] Main: Recorder test complete, 16 threads.
104892240 [10.004573:0x10d46346c] Main:   Iterations           =  104892232
104892241 [10.004574:0x10d4634c3] Main:   Iterations / ms      =      10489
104892242 [10.004574:0x10d463527] Main:   Duration per record  =         95ns

The first column is the *order* of records, a sequence number that helps relate records made from different threads. The second column is the time stamp in seconds from the first record. On 32-bit machines, it is precise to the ms. On 64-bit machines, it is precise to the microsecond. The third column is the location in the program where the record was taken, which you can use in a debugger to identify the code that was recording. The last part of the record is what was recorded.

See the project page for more details, and this blog article for a more extensive description of the design and rationale.