Join GitHub today
GitHub is home to over 36 million developers working together to host and review code, manage projects, and build software together.Sign up
RaptorJIT+Studio: Analyzing the evolving C heap of a JIT compiler #20
Let me tell you about a ~~~cute hack~~~ long story for logging and making sense of diagnostic data from the RaptorJIT virtual machine. (Note: The pretty screenshots are at the bottom.)
RaptorJIT is a high-performance Lua virtual machine (LuaJIT fork) and it has to reconcile a couple of tricky requirements for diagnostics. On the one hand we need full diagnostic data to always be available in production (of course!) On the other hand production applications need to run at maximum speed and with absolute minimum latency. So how do we support both?
The approach taken here is to split the diagnostic work into two parts. The RaptorJIT virtual machine produces raw data as efficiently as possible and then separate tooling analyzes this data.
The virtual machine is kept as simple and efficient as possible: the logging needs to be enabled at all times and there can't be any measurable overhead (and certainly not any crashes.) The logging also needs to be comprehensive. We want to capture the loaded code, the JIT compilation attempts, the intermediate representations of generated code, and so on.
The analysis tooling then has to absorb all of the complexity. This is tolerable because it runs offline, out of harms way, and can be written in a relaxed high-level style. Accepting the complexity can be beneficial too: making the tooling understand internal data structures of the virtual machine makes it possible to invent new analysis to apply to existing data. That's a lot better than asking users, "Please take this updated virtual machine into production, make it crash, and send new logs."
Let's roll up our sleeves and look at how this works.
The RaptorJIT diagnostic data production is implemented in lj_auditlog.c. It's only about 100 LOC. It opens a binary log file and writes two kinds of message in msgpack format. (Aside: msgpack rocks.)
The first kind of log message is called
The second kind of log message is called
The same piece of memory can be logged many times to track its evolution. The memory references in event log messages are understood to refer to the memory at the time the event was logged. So when the tooling wants to "peek" a byte of process memory it will need to search backwards in the log starting from the event of interest. This way we can track the evolution of the process heap and allow the VM to reuse the same memory for different purposes e.g. reusing the same JIT datastructures to compile different code at different times.
Here is what some raw log looks like when decoded from binary msgpack into json:
We can read this backwards:
Half-mission accomplished! The RaptorJIT virtual machine is now exposing its raw state to the outside world very efficiently, and the code is so simple that we can be confident about putting it into production.
The second part of the problem is to extract high-level information from the logs. We are not interested in reading hex dumps! We want the tooling to present really high-level information about which code has been JITed, how the compiled code has been optimized, which compilation attempts failed and why, and which code is hot in the profiler, and so on.
We solve this problem using Studio, which is "an extensible debugger for the data produced by complex applications." Studio is the perfect fit for this application - as it should be, since this problem was the motivation for creating the Studio project :-).
We take the direct "brute force" approach. This is conceptually like reading a coredump into gdb and writing macros to inspect it, but Studio means the tools will be written in Pharo Smalltalk with any awkward chores offloaded with Nix scripts.
Here is the plan of attack:
Let's do this!
Read RaptorJIT DWARF metadata
Looking at DWARF for the first time, several things are immediately apparent:
This is great news: it means that we are perfectly justified in cheating. (The alternative would be to become DWARF experts, but what we are really trying to do here is develop a JIT compiler, remember?)
Cheating is easy with Nix. Nix provides "dependency heaven." We can write simple scripts, we can use arbitrary versions of random utility programs, and we can be confident that everything will work the same way every time.
We create a Nix API with an
The Nix code works in three steps:
(Why YAML in the middle? Just because it's easier than JSON to generate from awk.)
Sounds horrible, right? Wrong! Nix has stone-cold control of all of these dependencies. Each run will produce exactly the expected results, using exactly the same versions of readelf/awk/python/etc.
(Nix is a big deal. Check it out over at InfoQ if you haven't already.)
Decode application types
Now we want to read the preprocessed JSON DWARF metadata and use it to make plain old objects out of the auditlog. There is no magic here: we write Smalltalk code to do exactly that!
This is not rocket science but it does take a bit of typing. The good news is that we can reuse the DWARF support code in the future to decode other programs compiled with C toolchains.
Extend the Glamorous Toolkit
Now the fun starts. It only takes a page or two of code to teach the graphical GTInspector how to display and navigate through the C objects in the log. Here is what that looks like (excerpted from the Studio Manual):
This is nifty: now we can clickety-click out way around to see what data we have. The representation is low-level but it does have access to all the C type definitions, typedef names, enum and
Visualize more complex objects
Now the pressure is on: we need to actually present some useful high-level information! This turns out to be pretty fun and easy using the high-level frameworks that Pharo provides. We can whip up step-by-step multi-panel navigation flows, we can present objects visually, and we can interactively "drill down" on everything using buttons / clicks / mouseovers / etc.
Here is one example view: browsing profiler data to see which JIT code is "hot" and then visualizing the way this code was compiled. The graph shows the compiled Intermediate Representation instructions arranged using their SSA references (data dependencies.)
The objects that we see on the screen are all backed by Smalltalk objects that are initialized from the log, each object can be viewed in multiple different ways, and we can navigate the links between objects interactively. It's really fun to click around in :-).
So! We wanted the RaptorJIT VM to efficiently log raw diagnostic data, and we wanted to create convenient developer tools for out-of-harms-way offline analysis. We have done both. Problem solved!
If you find this kind of hacking interesting then consider Watching the RaptorJIT and Studio repositories on Github. The projects are new - especially Studio - so don't be shy to ask questions with Issues!