Systems Performance 2nd Ed.



BPF Performance Tools book

Recent posts:
Blog index
About
RSS

DTrace pid Provider Instructions

16 Feb 2011

I originally posted this at http://dtrace.org/blogs/brendan/2011/02/16/dtrace-pid-provider-instructions.

The intent of this series of pid provider posts is to share my real-world experience in using the DTrace pid provider and its various features. Here I'll discuss another pid provider topic: the instruction offset probe.

Instruction Offset Probe

The instruction offset probe allows individual instructions to be traced. In my post about the pid provider return probe, the return instruction offset was visible as arg0, providing a hint at the code path taken. This could also be determined by tracing other sub-functions, or examining entry arguments and inspecting the source code. However, by using the instruction offset probe we can directly observe the code path taken. Leaving the last field of the probe description blank will match the "entry" and "return" probes, and the instruction offset probes:

# dtrace -n 'pid$target:libc:strlen:' -p 809
dtrace: description 'pid$target:libc:strlen:' matched 24 probes
CPU     ID                    FUNCTION:NAME
  1  63860                     strlen:entry
  1  76199                         strlen:0
  1  76200                         strlen:4
  1  76201                         strlen:9
  1  76202                         strlen:b
[...]
  0  76216                        strlen:37
  0  76217                        strlen:3c
  0  76213                        strlen:31
  0  76214                        strlen:34
[...]
DTrace can trace individual user-level instructions.

The first line of output says that DTrace "matched 24 probes": two for "entry" and "return", and 22 instruction offset probes. The output has been truncated to fit, but includes a jump from instruction offset 3c to 31. Examining that instruction in a debugger (here I used mdb):

libc.so.1`strlen+0x3c:          jne    -0xb     <libc.so.1`strlen+0x31>

So, not surprisingly, that instruction was a jump (jump not equal to), to offset 0x31.

Out of Memory

Software is usually made up of thousands of functions, and those functions are usually made up of dozens of instructions. This results in many hundreds of thousands of instructions, if not millions, that can be probed using DTrace. To put this to the test, I'll list all instructions from all functions in libc:

# dtrace -ln 'pid$target:libc::' -p 809 | wc -l
  157789

That's 157,788 probes, just for libc. Matching all instructions in this program, a bash shell, by using a wildcard for the second field as well:

# dtrace -ln 'pid$target:::' -p 809 | wc -l
dtrace: invalid probe specifier pid$target:::: failed to create offset probes in
'setup': Not enough space
       0

And there isn't enough memory for DTrace to complete. It's trying to create millions of probes, just for a shell process. Other applications (e.g., a web browser) are likely to have even more instructions.

Be careful with probe wildcards, you may try to instrument too much.

This is true regardless of which field is a wildcard. It's especially true of the last field, because that matches instruction offset probes as well, and so to make this point specifically:

Always use entry and return probes. Don't match instructions by accident.

Unless you really want to trace instructions for some reason. In my years of using DTrace, I've only needed to trace instructions about a dozen times (one of which has been included in the DTrace Book).

Specifying Offset

Instead of tracing all instruction probes (like above) to follow a code path, you can specify just a single instruction probe. Picking a single instruction probe is much safer - this causes less overhead on the target than tracing all instructions. For example, the dissassembly of strlen() is (via mdb):

> strlen::dis
libc.so.1`strlen:               movl   0x4(%esp),%eax
libc.so.1`strlen+4:             testl  $0x3,%eax
libc.so.1`strlen+9:             jne    +0x28    <libc.so.1`strlen+0x31>
libc.so.1`strlen+0xb:           nop    
libc.so.1`strlen+0xc:           movl   (%eax),%edx
libc.so.1`strlen+0xe:           movl   $0x7f7f7f7f,%ecx
libc.so.1`strlen+0x13:          andl   %edx,%ecx
libc.so.1`strlen+0x15:          addl   $0x4,%eax
libc.so.1`strlen+0x18:          addl   $0x7f7f7f7f,%ecx
libc.so.1`strlen+0x1e:          orl    %edx,%ecx
libc.so.1`strlen+0x20:          andl   $0x80808080,%ecx
libc.so.1`strlen+0x26:          cmpl   $0x80808080,%ecx
libc.so.1`strlen+0x2c:          je     -0x20    <libc.so.1`strlen+0xc>
libc.so.1`strlen+0x2e:          subl   $0x4,%eax
libc.so.1`strlen+0x31:          cmpb   $0x0,(%eax)
libc.so.1`strlen+0x34:          je     +0xc     <libc.so.1`strlen+0x40>
libc.so.1`strlen+0x36:          incl   %eax
libc.so.1`strlen+0x37:          testl  $0x3,%eax
libc.so.1`strlen+0x3c:          jne    -0xb     <libc.so.1`strlen+0x31>
libc.so.1`strlen+0x3e:          jmp    -0x32    <libc.so.1`strlen+0xc>
libc.so.1`strlen+0x40:          subl   0x4(%esp),%eax
libc.so.1`strlen+0x44:          ret    

Let's pick the 0x2e instruction to see if that was reached:

# dtrace -n 'pid$target:libc:strlen:2e' -p 14304
dtrace: description 'pid$target:libc:strlen:2e' matched 1 probe
CPU     ID                    FUNCTION:NAME
  1  86169                        strlen:2e
  1  86169                        strlen:2e
  1  86169                        strlen:2e
^C

In this case, it was - shedding light on the code path taken.

Summary

The pid provider instruction offset probe allows individual instructions to be traced in user-land code. The performance cost for DTrace observability is usually negligible; however, this is a case where the performance cost can be high - when tracing multiple instructions that are called frequently.

It's most important just to remember that this feature exists, so that you can avoid using it accidentally via probe name wildcards. You can revisit the docs if you hit a case where you really need to use it.