How the recorder works inside your process

While you record, every call to one of your own methods passes through a small piece of C in front of the method. It writes down the call and gets out of the way. This page says what that costs you and what it can and cannot do to your program.

What runs on each call

When you start recording, the gem puts a wrapper in front of each of your methods. The wrapper is C. On a call it has seen before, it writes one row: which tree and step the call is, where it was called from, and from tier 2 the class of each argument, from tier 3 their object ids. It builds that row on the stack, copies it into an 8 MB buffer the recorder owns, and calls your method. At tier 3 it writes a second row when your method returns.

The first call on a new route, and any call into a gem you have asked to record, goes through the gem’s Ruby code once. That is where the route and the strings in it get their numbers for this segment. Every later call like it is written by the wrapper alone.

A writer thread takes rows out of the buffer in batches of up to 8,192 and writes them to the segment files under tmp/runtime_analysis, one file per thread per segment. It waits up to two milliseconds to gather a batch rather than writing a row at a time, and it flushes the file once it has caught up. It runs without Ruby’s Global VM Lock, so it never competes with your threads for it.

With adaptive mode on, the recorder keeps a route’s first call and one repeat in 64. A skipped call takes its step on the tree, calls your method, and writes nothing.

What it never does to your program

Your private methods stay private. Ruby decides private, protected and module_function by looking at the calling frame, and it skips the wrapper’s C frame when it looks. A wrapper written in Ruby would put a frame of its own there and change what those keywords do while you record, which is why there is no pure-Ruby recorder. Without the compiled extension the gem still loads and reads recordings, and starting a recording raises RuntimeAnalysis::Native::Missing.

It keeps nothing of yours. Nothing in the buffer is a Ruby object. The wrapper copies what it needs into memory the recorder owns, so the garbage collector and compaction run as they always do, and the writer thread never reads your heap. Recording in Ruby would allocate on every call and leave the collector to clean up; the C row allocates nothing.

It never makes your thread wait. Your thread holds the GVL while the wrapper runs, so a wait there would stop every Ruby thread in your application. The wrapper tries for the buffer’s lock for at most 50 microseconds. If it cannot have it, the row is dropped and counted.

It never raises into your method. A full buffer, a failed allocation and a failed internal check each lose rows from the recording. None of them raises in the method being recorded.

A fork starts clean. The child abandons the recorders it inherited, without flushing their files, so the parent’s unwritten rows are written once, by the parent. The child opens its own.

What a recorded call costs

These figures are a worst case: a loop of one-line methods, where the wrapper is nearly all of the running time. What recording costs has the measurements on Redmine’s test suite and on a server under traffic.

• A call that goes through Ruby costs more than one the wrapper writes by itself.
• On your thread, a repeated call costs a table lookup, the row, one try at the lock and a copy into the buffer. Tier 3 adds an object id for every value and the second row on return.
• The writer thread spends 63 to 75 nanoseconds on a row, about half the time your thread takes to make one at tier 1.
• A string is copied once for each segment that uses it.
• File writes are batched. Once or twice in a run the operating system holds a single write for 3 to 15 ms, and the buffer holds the rows your program produces in that time.

When the recorder has a fault

A fault in the recorder loses rows from the recording. Your application keeps running.

• Dropped rows. A full buffer drops the row and counts it, and so does a lock your thread could not take within its budget. RuntimeAnalysis.stats reports the count. In the recording, a dropped call is a gap in that tree’s step sequence, and a dropped name leaves later rows with that id reading as an empty label.
• The buffer is 8 MB to make drops rare. In sixty runs of the benchmark at each size, 19 runs dropped rows with a 2 MB buffer, one with 4 MB and none with 8 MB. In fifteen recorded runs of Redmine’s test suite, one dropped a single row. Recording Campfire with every gem at tier 4, one run of three dropped 66,109 of 30.3 million rows.
• A failed check stops one stream. Before each access to its own buffers the recorder checks what it is about to read: a row’s length and kind, a tail whose tier or count makes sense, a file that is open. A check that fails means the code was about to step outside its buffers, so it refuses, and that one thread’s recorder is disabled. Its rows are dropped from then on and its writer stops. The gem notices at the first step of that thread’s next tree, closes the stream and opens a new one. The thread loses the rows between the fault and that tree. The first fault on a stream is written to stderr once, and only if stderr can take it without blocking.
• A failed allocation does not raise. A string that cannot be copied is dropped and counted, and a table that cannot grow sends its calls through Ruby instead. The one exception is opening a recorder: if that fails, the half-built recorder is freed and you get a Ruby exception.
• A file that cannot be written is reported. A segment that cannot be opened when the recording rolls over, and a write error on a file, are each reported to stderr. A failed roll leaves the thread writing to its current file.
• Strings are kept as they were. The recorder escapes strings itself and passes bytes of 0x20 and above through as they are, so a Ruby string that is not UTF-8 gives a line that is not valid JSON. The bytes in the recording are the bytes your program had.