Intel Processor Trace: How to use it

To be noted is that “Processor Trace” is a feature of recent Intel x86 processor (eg skylake):

https://software.intel.com/en-us/blogs/2013/09/18/processor-tracing

First clone this:

https://github.com/01org/processor-trace

And do a “sudo make install” to install the libipt.so libraries.

Next do a clone of Andi Kleen pt tracing tool:

git clone github.com:andikleen/simple-pt

If you do “make install” is to make the kernel module, and then followed by “sudo insmod simple-pt.ko” to load it.

Next is to “make user” to make all the relevant binaries (see Makefile, which is essentially sptdump, fastdecode, sptdecode and ptfeature).

During compilation you make encounter some errors on missing files, and the following are the ones I need to install before successful “make user” (but your mileage may differ):

sudo apt-get install libelf-dev
 sudo apt-get install libdw-dev dwarfdump
 sudo apt-get install libdwarf-dev

There are other binaries like “rdmsr” which the tester program depends as well.

Next is to run tester as root: “sudo ./tester”, and the output is listed here:

http://pastebin.com/d3QeVNsV

And looking further into “stest.out”:

0 [+0] [+   1] native_write_msr_safe+18
 [+  31] trace_event_raw_event_msr+116 -> trace_event_buffer_reserve
 [+  21] trace_event_buffer_reserve+143 -> trace_event_buffer_lock_reserve
 [+  23] trace_event_buffer_lock_reserve+67 -> trace_buffer_lock_reserve
 [+  13] trace_buffer_lock_reserve+33 -> ring_buffer_lock_reserve
 [+  41] ring_buffer_lock_reserve+184 -> rb_reserve_next_event
 [+  36] rb_reserve_next_event+180 -> trace_clock_local
 [+   5] trace_clock_local+20 -> sched_clock
 [+   4] sched_clock+12 -> native_sched_clock
 [+   7] trace_buffer_lock_reserve+65 -> ring_buffer_event_data
 [+   4] ring_buffer_event_data+12 -> rb_event_data
 [+   6] trace_buffer_lock_reserve+90 -> tracing_generic_entry_update
 [+   7] trace_event_buffer_reserve+176 -> ring_buffer_event_data
 [+   4] ring_buffer_event_data+12 -> rb_event_data
 [+  11] trace_event_raw_event_msr+164 -> trace_event_buffer_commit
 [+  33] trace_event_buffer_commit+124 -> filter_check_discard
 [+  11] trace_event_buffer_commit+226 -> trace_buffer_unlock_commit
 [+  15] trace_buffer_unlock_commit+45 -> ring_buffer_unlock_commit
 [+  16] ring_buffer_unlock_commit+54 -> rb_update_write_stamp
 [+   7] trace_buffer_unlock_commit+115 -> ftrace_trace_userstack

It is generated by the sptdecode command:

sptdecode --sideband ${PREFIX}.sideband --pt ${PREFIX}.0 $DARGS > ${PREFIX}.out

The function “trace_event_raw_event_msr” is nowhere to be found inside simple-pt.c, nor part of the kernel symbols. But “trace_event_buffer_reserve” is part of the kernel symbol (sudo cat /proc/kallsyms |grep trace_event_buffer_reserve).

So now we shall disassemble the APIs shown in the stest.out from the live-running kernel (every is still read-only, so is safe, no modification is possible, but you will need root):

To see the APIs live in action, first identify the “vmlinux” where the kernel is build. Mine is build by myself, and so do this (sudo is needed before /proc/kcore is root read-only):

sudo gdb ./vmlinux /proc/kcore ==> gdb prompt.

And next is to identify the source directory of the simple-pt.ko kernel module, and its offset in memory:

sudo cat /proc/modules |grep simple
 simple_pt 61440 0 - Live 0xffffffffa1021000 (OE)
 

And so add the following inside the gdb prompt:

 add-symbol-file /home/tteikhua/simple-pt/simple-pt.ko 0xffffffffa1021000

Now you can list in assembly by name:

(gdb) x /10i trace_event_raw_event_msr
 0xffffffffa1022c70 <trace_event_raw_event_msr>: push %rbp
 0xffffffffa1022c71 <trace_event_raw_event_msr+1>: mov %rsp,%rbp
 0xffffffffa1022c74 <trace_event_raw_event_msr+4>: push %r15
 0xffffffffa1022c76 <trace_event_raw_event_msr+6>: push %r14
 0xffffffffa1022c78 <trace_event_raw_event_msr+8>: push %r13
<snip>
 0xffffffffa1022ccd <trace_event_raw_event_msr+93>: lea -0x58(%rbp),%rdi
 0xffffffffa1022cd1 <trace_event_raw_event_msr+97>: mov $0x20,%edx
 0xffffffffa1022cd6 <trace_event_raw_event_msr+102>: mov %r12,%rsi
 0xffffffffa1022cd9 <trace_event_raw_event_msr+105>: addq $0x1,0x7d27(%rip) # 0xffffffffa102aa08
 0xffffffffa1022ce1 <trace_event_raw_event_msr+113>: mov %ecx,-0x5c(%rbp)
 0xffffffffa1022ce4 <trace_event_raw_event_msr+116>: 
callq 0xffffffff81205060 <trace_event_buffer_reserve>  
0xffffffffa1022ce9 <trace_event_raw_event_msr+121>: addq $0x1,0x7d1f(%rip) # 0xffffffffa102aa10

From the “stest.out” output above, we can also see that the line by line output correspond to each “basic blocks” (https://en.wikipedia.org/wiki/Basic_block) in the assembly listing.

References:

https://lwn.net/Articles/576551/

https://lwn.net/Articles/584539/

https://lwn.net/Articles/654705/

https://lwn.net/Articles/648154/