Intro to Trace Inspector that displays Ruby trace logs with pretty UI

Naoto Ono — Wed, 24 May 2023 09:33:26 +0000

Trace Inspector, a tool that displays Ruby trace logs with pretty UI while debugging in VS Code, has recently landed in debug.gem. debug.gem is a Ruby standard debugger library and the default debugger in Rails. Since debug.gem supports VS Code, you can debug Ruby programs in vscode-rdbg.

What is unique about Trace Inspector compared to existing tracing tools is its cool UI. Trace Inspector give you the following benefits:

Intuitive viewing of the trace logs.
Check parameters and a return value for the trace log on the editor.
Record the backtrace and local variables if necessary.

Trace Inspector helps you to read complex code.

Use cases for Trace Inspector

We envisage two use cases:

Code reading to get a rough idea of the process
Tracking detailed behaivor during debugging

In other words, Trace Inspector is useful for code reading with a debugger. You may feel that code reading with a debugger is helpful, reading complex code is still hard. The difficulty of reading complex code with a debugger is that we have to remember all the different kinds of information at the points where we have paused until now. However, it's almost impossible. We may forget which method was called at a previous stopping point. Also, we may forget the method's parameters or a return value. This is a problem of code reading with a debugger.

To solve the problem, we can use Trace Inspector. If we use Trace Inspector, we don't have to remember all the different kinds of information. We can check the information anytime. Also, we can copy the parameters and return values by clicking the target log.

Comparison with existing tracing tools

There are some existing tools for tracing programs in Ruby. For example, ruby/tracer is one of the famous tracing tools. Also, debug.gem already had a feature for tracing programs in the terminal. One of the characteristics of the existing tools is that the terminal is used as a front-end. Although the terminal is helpful, we thought we could provide richer user experiences by using VS Code from the following advantages.

The first advantage is the way of displaying trace logs. The following are examples of tracing a program with debug.gem in the terminal and tracing a program with Trace Inspector. The white bordered area is a single trace log. If we use Trace Inspector, we can see only what we want to see by clicking. In this picture, the trace logs in target.rb:5 are collapsed. We can say "I'm not interested in the trace logs here, so let's just collapse it".

Tracing a program with debug.gem in the terminal

Tracing a program with Trace Inspector

The second advantage is that trace logs can be viewed on the editor. If we click the specified log, the target file is opened, and the line is highlighted on the editor. Also, parameters and return values are displayed there.

How to use Trace Inspector

How to start Trace Inspector

Set a breakpoint where it says, "puts set a breakpoint here" in the code.
Start debugging.
Click "TRACE INSPECTOR" view in the Sidebar to open it.
Click "Enable Trace" button in "TRACE INSPECTOR" view.
Click "Continue" in debug toolbar to resume the program.
The trace log appears in "TRACE INSPECTOR" view.

Congratulations! You were able to trace the log with Trace Inspector!

Diving into trace logs

Trace logs are arranged in the order in which they are executed. For example, target.rb:9 was executed before target.rb:10 in this case.

There are several kinds of icons in trace logs, as follows:

Line trace Log

An icon such as a location icon is a Line trace log. It traces which line is executed. If you click the Line Trace log, the target file is opened, and the line is highlighted.

Call trace log

A right arrow icon is the Call trace log. It traces which method is called. If you click the Call trace log, parameters are displayed on the editor in addition to the highlighting lines.

Return trace log

A left arrow icon is the Line trace log. It traces which method is returned. If you click the Call trace log, a return value is displayed on the editor in addition to the highlighting lines.

Recording mode

If we use Recording mode, we can record local variables and backtraces. Local variables and backtraces at the point of execution can be checked. For example, we can see how local variable A is assigned. The step to use this option is almost the same as described above. You need to click "•••" (more icon), then put a checkmark of "Record And Replay (Slow)" before clicking the "Enable Trace" button.

Set a breakpoint where it says, "puts set a breakpoint here" in the code.
Start debugging.
Click "TRACE INSPECTOR" view in the Sidebar to open it.
Click "•••" (more icon), then put a checkmark of "Record And Replay (Slow)"
Click "Enable Trace" button in "TRACE INSPECTOR" view.
Click "Continue" in debug toolbar to resume the program.
The trace log appears in "TRACE INSPECTOR" view.

Options for tracing

"Trace Line" and "Trace Call/Return" is enabled in the default. The lower the table you go, the more log kinds you take.

	Location	Method name & Params	Return Value	Backtraces	Local variables
Trace Line (Default)	✓	N/A	N/A
Trace Call/Return (Default)	✓	✓	✓
Record And Replay	✓	✓	✓	✓	✓

Some tips

Tracing only matched events that match specified regular expressions

You can trace only the events that you want.

Click "Apply filter by Regexp"
Enter any string. (Also, you can filter by file path such as "target.rb")

Copying a trace log

You can copy trace logs as JSON objects.

Right-click a log that you want to copy.
Click "Copy Trace log"

Here is an example of JSON objects.

{
  "method": "Object#bar",
  "location": { "path": "/Users/s15236/workspace/debug/target.rb", "line": 4 },
  "parameters": [
    { "name": "c", "value": "10" },
    { "name": "d", "value": "20" }
  ]
}

Checking the process flow in frame-by-frame

By clicking the arrow, you can check the process flow in frame-by-frame. The down arrow goes to the next log such as "Step Into". The up arrow goes to the previous log such as "Step Back".

Configuring the maximum size of trace logs that a debugger will save

In the default, the maximum size of trace log stored by a debugger is 50000. If the size of trace logs exceeds the maximum size, the excess is removed from the oldest of the existing logs, and the new logs are inserted. You can change the setting as follows:

Performance comparison for each option

Execution time always depends on the program. Thus, what we should focus is how much slower it is compared to normal. We can use Trace Line without worrying about anything since Trace Line is only 17 times slower than Normal run. We may feel a little slow when using Trace Call because Trace Call is only 203 times slower than Normal run. We need to accept that it will be a slow execution before starting Record And Replay. However, we plan to improve the perfomance for Record And Replay.

	Execution Time(s)	Ratio to Normal run
Normal run (Without tracing)	0.107	1.0
Trace Line	1.886	17.6
Trace Call/Return	21.729	203.1
Record And Replay	1,102.955	10,308.0

Here is a script for measuring performance. This script is the part of Rails application.

def index
  binding.break # <- Start a program here
  10_000.times {
    respond_to do |format|
      format.html # index.html.erb
    end
  }
end #<- Pause a program here

ruby 3.2.1 (2023-02-08 revision 31819e82c8) [arm64-darwin21]
MacBook Pro (16-inch, 2021)
Chip: Apple M1 Max
Memory: 32 GB

Conclusion

I hope that you enjoy tracing Ruby programs with Trace Inspctor. Also, we look forward to your feedbacks!

Acknowlegement

Special thanks to Koichi Sasada-san. He helped me to design Trace Inspector!

DEV Community: Naoto Ono