This post is about how I made the Rails Trace tool to help people better understand the internals of Rails.

❤️ Rails

What makes Rails a pleasure to use is that you can often create something that does exactly what you want by writing very little code.

You can do this because Rails handles all the machinery common to most web applications such as parsing URL parameters or talking to your database. But all of this machinery is hidden so you might find it hard to picture how all the parts of Rails and it’s dependencies work together. For example, you might not know how a web server such as Puma talks to Rails or how your controller actions get called. Having a better understanding of the internals of Rails it might help you to debug an issue with your application or to be able to contribute to Rails itself.

📹 Capturing the Trace

I first wanted to capture information about all the methods called as Rails responded to a request so I could experiment with different ways to present it.

Ruby comes included with TracePoint, which is a way you can listen for certain events when your code is run such as a line of code being executed or a class being defined. I was interested in the :call and :return events which occur when a method gets called or returns.

I created an example Rails application and made it print TracePoint events as they happened. After making a request to the application I saved the event log to a file that I could process later.

🕵️‍ A Sidequest: Missing Return Events

After running the trace a few times I was surprised to find that the number of method :call events I had logged was greater than the number of :return events. How could a method be called but never return?

I used the log to find one of the methods in Rails that was missing a return. I thought the method may be raising an exception which was bubbling up the call stack and preventing itself from returning, but couldn’t see any exception events in my log.

I made a copy of the class and called the method and saw the same problem when I added TracePoint again. I kept removing code from the class until I was left with a minimal example and was able to submit a bug to Ruby about the missing events.

The problem occurred because of the way that Ruby optimises code. Before your Ruby code runs it’s translated into lower level instructions that the Ruby Virtual Machine can understand. Flags are added at this point to certain instructions so that TracePoint knows what events to log later as your code runs. You can see examples of these flags in the proposal to introduce TracePoint. Ruby then tries to optimise the compiled code to make it run faster by recognising patterns of instructions and making changes to them. One of the optimisations, called peephole optimisation, meant that the flags that TracePoint relied on were removed or skipped.

This particular bug should be fixed in the next version of Ruby (2.6.2). I worked around the problem by disabling peephole optimisation before the code I wanted to trace ran:

RubyVM::InstructionSequence.compile_option = {
   peephole_optimization: false
}

📐 Rendering the Trace as an SVG with React

Once I had the log of method calls I wrote a script to process it. I used a recursive function to match up method calls to returns to make the data easier to render. The script also identified what code belonged to which Gem and cleaned up file paths.

I wanted to create an SVG to display the trace since I’ve found they work well to show information that would be difficult to render with HTML elements alone. The crossword component I worked on used React to render an SVG-based crossword grid, and I also used an SVG to draw a Voronoi diagram on top of a map with d3. Using React, I generated an SVG where every method call was represented with a rect element.

I used Grommet for the first time to make it easier to style the site that I created to display the trace. I found Grommet was really helpful to bootstrap the look and feel of the page by providing reusable components such as headings and tabs. As I added other tools to the project I found it difficult to get Grommet to work well with them. Both React router and Grommet had their own components they wanted me to use to create links and I didn’t find a way to combine the behaviour of both. When I introduced react-snap to pre-render my site I found that Grommet’s Layer component didn’t work with it because it modified the DOM outside of React.

The first trace I recorded had around 10,000 method calls to render. I found that my browser struggled to handle this many elements and the trace itself was hard to follow. Two large parts of the trace were Rails loading the database schema and compiling the view template. Rails caches both of these actions the first time they are needed so I warmed caches by performing additional requests before starting my trace. This left me a with a more manageable ~2000 method calls to draw.

You can explore the trace yourself. I’m also keen to find other resources to link to from the trace that are good explainers of the internals of Rails.