Virtual Trace

By Jakob Engblom

Engblom_lg I spent most of last week at the S4D conference in Southampton, the UK. A small gathering of people interested in debug, it seems to be a good indicator of trends in debug. The dominant trends this year were clearly tracing and instrumentation. From the perspective of a virtual platform, tracing is a natural task, and it can be done with much less pain than on a physical platform.

Tracing on a piece of hardware requires that the processor or SoC at the heart of the system has an interface that can communicate a trace to an external trace box, and also that the chip has built-in tracing in the hardware. The trace units we have today are much more powerful than those of just a few year's ago, but trace is still not universal, not able to capture everything, and limited by the bandwidth of the few pins you can pull out of a target for the purpose of debug. The result is that you always end up tracing only certain aspects of the execution or only certain subcomponents of an SoC. In particular data trace is not always supported, and tracing the behavior and accesses to peripheral devices is usually hard.

In a virtual platform, tracing has unlimited bandwidth since it goes straight from the simulator to the host. As the time inside the virtual platform is virtual, it does not matter if tracing slows down the execution – the time seen by the virtual machine is the same regardless, and the tracing is invisible to the simulated system. You can trace any part of the target system, including the rare luxury of complete data access traces undisturbed by caches and buses hidden deep inside an SoCs.

Here are some tracing examples done with Simics, just to give a flavor what can be done. We start with a simple instructions + data trace (from a point about 2 seconds into the boot of VxWorks 6.8 on a Freescale P2020):

simics> trace0.start
Tracing enabled. Writing text output to standard output.
simics> c 10
inst: [  51] CPU 0 <v:0x0100075c> <p:0x00100075c> 3b7b0002 addi r27,r27,2
inst: [  52] CPU 0 <v:0x01000760> <p:0x001000760> b3df0000 sth r30,0(r31)
data: [  467] CPU 0 <v:0xffef5eca> <p:0x0ffef5eca> Write 2 bytes 0xffff
inst: [  53] CPU 0 <v:0x01000764> <p:0x001000764> 3860000a li r3,10
inst: [  54] CPU 0 <v:0x01000768> <p:0x001000768> 4bfffe79 bl 0x10005e0
inst: [  55] CPU 0 <v:0x010005e0> <p:0x0010005e0> 9421ffd0 stwu r1,-48(r1)
data: [  468] CPU 0 <v:0x01316470> <p:0x001316470> Write 4 bytes 0x13164a0
inst: [  56] CPU 0 <v:0x010005e4> <p:0x0010005e4> 7c0802a6 mflr r0
inst: [  57] CPU 0 <v:0x010005e8> <p:0x0010005e8> bf61001c stmw r27,28(r1)
data: [  469] CPU 0 <v:0x0131648c> <p:0x00131648c> Write 4 bytes 0x132db1c
data: [  470] CPU 0 <v:0x01316490> <p:0x001316490> Write 4 bytes 0xaaaa
data: [  471] CPU 0 <v:0x01316494> <p:0x001316494> Write 4 bytes 0xf8000000
data: [  472] CPU 0 <v:0x01316498> <p:0x001316498> Write 4 bytes 0xffff
data: [  473] CPU 0 <v:0x0131649c> <p:0x00131649c> Write 4 bytes 0xffef5eca
inst: [  58] CPU 0 <v:0x010005ec> <p:0x0010005ec> 7c7f1b79 mr. r31,r3
inst: [  59] CPU 0 <v:0x010005f0> <p:0x0010005f0> 90010034 stw r0,52(r1)
data: [  474] CPU 0 <v:0x013164a4> <p:0x0013164a4> Write 4 bytes 0x100076c
inst: [  60] CPU 0 <v:0x010005f4> <p:0x0010005f4> 3ba00000 li r29,0


Simics can also trace accesses to devices in a system (and many many other things). Here is an example of keeping an eye on accesses to the main serial port in the P2020 system. The data reported include the processor accessing the device, as well as address accessed and the exact cycle when the access hits.

[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157a70 3064639465}
Read from p2020ds.soc.cpu[0]: PA 0x4504 SZ 1 0x8 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639565}
Write from p2020ds.soc.cpu[0]: PA 0x4503 SZ 1 0x83 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639582}
Write from p2020ds.soc.cpu[0]: PA 0x4500 SZ 1 0x58 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639602}
Write from p2020ds.soc.cpu[0]: PA 0x4501 SZ 1 0x14 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639622}
Write from p2020ds.soc.cpu[0]: PA 0x4503 SZ 1 0x3 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639688}
Write from p2020ds.soc.cpu[0]: PA 0x4501 SZ 1 0x0 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639713}
Write from p2020ds.soc.cpu[0]: PA 0x4503 SZ 1 0x3 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639733}
Write from p2020ds.soc.cpu[0]: PA 0x4504 SZ 1 0x8 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639753}
Write from p2020ds.soc.cpu[0]: PA 0x4502 SZ 1 0xc7 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157a70 3064639775}
Read from p2020ds.soc.cpu[0]: PA 0x4502 SZ 1 0xc1 (BE)
[p2020ds.soc.uart[0] trace-io] {p2020ds.soc.cpu[0] 0x157bf0 3064639801}
Write from p2020ds.soc.cpu[0]: PA 0x4502 SZ 1 0xf (BE)

Yet another example of tracing using Simics is the execution time line we have in the Simics Analyzer product. This traces the context switches of an operating system, providing a nice overview of the system execution. I wrote a blog post about Analyzer back in April, if you want to know more about that aspect.

The other theme was instrumentation. To get a grip on the execution of software stacks involving operating systems, hypervisors, middleware, custom devices drivers, and complex user-level programs, it is hard to beat inserting little snippets of instrumentation code into the software source code which report "now I am at place X in state Y". When the program is run and the instrumentation output traced, this results in a trace of events at a level very understandable to the programmers. It is "printf debugging" with less overhead and more sophistication. In theory, such a trace could be reconstructed from an instruction trace and using debug information, but in practice, inserting little application-specific tracers into the code gets us much more application-level information with much less programmer pain. If the instrumentation code is left inside a shipping system, it does not even amount to altering the nature of the programs – we are testing the same code as we ship! It is obviously not something for tight real-time code, but in many cases the time-savings in debug and development worth the slight execution overhead.

With a virtual platform, you can do interesting things with source-code instrumentation. Rather than pushing the instrumentation data out over a network or storing it in in-memory buffers, it can be sent to a special trace device that immediately saves the data onto the host disk (or send it across a network).

Interestingly for me, such an instrumentation device is the only hardware model written by me that is still shipping with Simics. The "simple-byte-dump" device maps a single byte in memory and copies anything written there into a file on the host. We used this with an aerospace customer to report results from on-target tests, without having to involve any serial or network drivers. Very simple, very effective, and a good example of what you can do with a virtual platform which is hard to do in hardware. If you have Simics, it is in there, and you can check it out yourself!