Resources

Author: Emiliano Testa, Staff Software Engineer at Undo

At Undo, we’re always experimenting with ways to improve usability and make the consumption of recordings more efficient and productive. One of our current experiments involves using a probe file in UDB and visualizing the results in the timeline. (If you are unfamiliar with this, check out our documentation on Post Failure Logging)

When used together, the info timeline command will display not only your bookmarks and current position but also all logs produced by Post Failure Logging (PFL) using the probe file you specify.

Skepticism is paramount

Initially, I was skeptical about this feature. Post Failure Logging is extremely useful, but I feared it would produce too much output to be practical in UDB. 

Boy, was I wrong!

The bug I was investigating

A customer reported a severe slowdown during recording, which caused their application to fail due to timeouts.

A quick review of their logs made it clear: an optimization I had previously implemented wasn’t working as expected.

In order to record the execution of software, the Undo engine needs to have intimate knowledge of what certain operations do. In this case, the operation was a single ioctl that I had optimized. In certain cases, it was still not being recognized, and therefore it was handled as “unknown”, making its recording much slower than it needed to be.

With the recording of the application in hand, I set out to understand why the specific ioctl was sometimes being treated as optimized and other times not.

My first step was to find the places where the ioctl was called. I wasn’t trying to understand the program’s logic; instead, I wanted to trace how the engine ended up recording it the way it did.

So, I jumped to the end of the recording and ran the below. This brought me to the relevant ioctl event.

Knowing that this application performed several different ioctl calls, I needed a way to filter for the specific one I cared about.

A quick look at the two registers confirmed this wasn’t the one. rsi contains the magic number, and rdi the file descriptor.

Using ugo event brought me to the ioctl() function. I then set a breakpoint that would only trigger when the rsi register contained the right value (the magic number I was looking for: 0x40bb4d06).

After stopping a few times and not finding anything wrong, I decided to change my strategy.

Using a probe file

It was time to create a probe file.

I wanted to log every ioctl() call and inspect what value rdi had when the rsi matched our target, but wasn’t being recognized.

I wrote a small probe file that logged every call to the ioctl() function and printed the values of both rsi and rdi.

With the probe file written, I launched the two commands needed to get the log and the information I was after:

And there it was: a request with magic number 0x40bb4d06 and file descriptor -1. 

This is what I suspected from the start, but I wanted to see it with my own eyes.

Pro tip

I used the UDB pipe (|) command to redirect the output to tee,  saving the output to the file ioct_timeline. That way, should I need to refer to it later, I don’t need to regenerate the logs.