DTrace pid Provider return

In my previous posts, I introduced the DTrace pid provider, and discussed function “entry” probes, their arguments, and the stability of these. Here I’ll continue discussing the pid provider, introducing the function “return” probe, return value, and the stability of these as well.

For more information on the pid provider, see the pid provider chapter of the DTrace Guide and the examples in the forthcoming DTrace Book.

Function Return Probe

The “entry” probe traces the start of a function, and the “return” probe traces the end. The name “return” comes from the “ret” assembly instruction, which is how a thread ends execution of a function and returns to the parent on the stack. Listing return probes for the bash shell on Solaris:

# dtrace -ln 'pid$target:::return' -p 809
   ID   PROVIDER            MODULE                          FUNCTION NAME
76293     pid809              bash                             __fsr return
76294     pid809              bash                        exit_shell return
76295     pid809              bash                           sh_exit return
76296     pid809              bash               shell_is_restricted return
76297     pid809              bash             maybe_make_restricted return
76298     pid809              bash                 disable_priv_mode return
76299     pid809              bash                       unbind_args return
76300     pid809              bash                  unset_bash_input return
[...6759 lines truncated...]

DTrace can trace the return of functions.

Tracing the return lets us examine the return value of functions, follow the code path, and measure the time spent for functions. For some functions, the entry arguments have a pointer which is only populated on return, which is only valid when examined in the return probe.

Return Value

# dtrace -n 'pid$target:libc:strlen:return { printf("%x %d", arg0, arg1); }' -p 809
dtrace: description 'pid$target:libc:strlen:return ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  69433                    strlen:return 44 8
  0  69433                    strlen:return 44 11
  0  69433                    strlen:return 44 11
  0  69433                    strlen:return 44 8
  0  69433                    strlen:return 44 2
  0  69433                    strlen:return 44 20

Here I’ve printed arg0 and arg1 for return. arg1 is the return value, showing the length of the string in bytes. arg0 is the program counter offset from where we left the function (assembly, “ret”). Functions can return from different points, so the address can shed light on which code path was taken (if it’s relevant).

This was the dissassembly of the strlen() function, using 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+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    

The “ret” is at address 0×44, which we found when using DTrace. Functions can have multiple return points.

I find arg0 for program offset a little confusing since I also frequently use the syscall provider, where arg0 (and arg1) both contain the return value.

The pid provider rval is available as arg1 (not arg0).
The function return offset is available as arg0.
arg1 is generally the one I’m interested in.

More Discoveries

I’m always discovering things using the pid provider, even when tracing standard system library functions such as these. Here I’m tracing the return of strcmp(), and printing the rval as a distribution plot summary:

# dtrace -n 'pid$target::strcmp:return { @ = quantize((int32_t)arg1); }' -p 210
dtrace: description 'pid$target::strcmp:return ' matched 2 probes
^C

           value  ------------- Distribution ------------- count
              -8 |                                         0
              -4 |@                                        36
              -2 |                                         0
              -1 |@                                        36
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      1253
               1 |@                                        24
               2 |@                                        36
               4 |                                         0
               8 |                                         12
              16 |@                                        36
              32 |                                         0

Interesting. I would have guessed that strcmp() only returned -1, 0 or 1, but it does in fact return other values as well. This is allowed, as the man page does say “The function returns an integer greater than, equal to, or less than 0,”. Wikipedia notes that most real-world implementations can return other values due to branching optimization.

Associating Entry to Return

Data in the entry probe can be associated with the return probe using the DTrace thread local variable. For example, the following script traces calls to fopen(), showing both the entry arguments (filename and mode) and the return value (success/failure).

# cat -n fopen.d
     1  #!/usr/sbin/dtrace -s
     2
     3  #pragma D option quiet
     4
     5  dtrace:::BEGIN { printf("Tracing fopen() on PID %d...\n", $target); }
     6
     7  pid$target::fopen:entry
     8  {
     9          self->file = arg0;
    10          self->mode = arg1;
    11  }
    12
    13  pid$target::fopen:return
    14  /self->file/
    15  {
    16          this->result = arg1 != NULL ? "success" : "failure";
    17
    18          printf("mode=%s result=%s file=%s\n", copyinstr(self->mode),
    19              this->result, copyinstr(self->file));
    20
    21          self->file = 0;
    22          self->mode = 0;
    23  }
# ./fopen.d -p 14550
Tracing fopen() on PID 14550...
mode=a result=success file=highscores_c
mode=r result=success file=highscores_c

The probes were associated using thread local variables, self->file and self->mode, which are associated with the current thread. One of these is tested on line 14, to ensure they have been set before dereferencing them on lines 18 and 19. It’s possible that DTrace was executed after the function entry and before the function return, which would result in only the return firing for that invocation – hence the test. These variables are then cleared by setting them to zero on lines 21 and 22.

Access entry arguments during the return probe by first saving them as thread local variables.

This won’t work for recursive functions, which can have multiple entries before a return.

Flow Indent

When tracing both entry and return probes, the DTrace flowindent option (-F) will print an output indented by stack depth – which shows the flow of code. Here is the bash shell on Solaris reading a single keystroke:

# dtrace -Fn 'pid$target:bash::entry,pid$target:bash::return' -p 809
dtrace: description 'pid$target:bash::entry,pid$target:bash::return' matched 2407 probes
CPU FUNCTION
  0  <- rl_getc
  0  <- rl_read_key
  0  -> _rl_dispatch
  0    -> _rl_dispatch_subseq
  0      -> rl_insert
  0        -> _rl_insert_char
  0          -> _rl_any_typein
  0          <- _rl_any_typein
  0          -> rl_insert_text
  0          <- rl_insert_text
  0        <- _rl_insert_char
  0      <- rl_insert
  0    <- _rl_dispatch_subseq
  0  <- _rl_dispatch
  0  -> rl_redisplay
  0    -> _rl_move_cursor_relative
  0    <- _rl_move_cursor_relative
  0    -> _rl_output_some_chars
  0    <- _rl_output_some_chars
  0  <- rl_redisplay
  0  <- readline_internal_char
  0  -> readline_internal_char
  0    -> _rl_init_argument
  0    <- _rl_init_argument
  0    -> rl_read_key
  0      -> _rl_next_macro_key
  0      <- _rl_next_macro_key
  0      -> rl_getc
^C

Back when DTrace was new, this sort of functionality had to be seen to be believed, and a demo was circulated showing a flow indent trace of the read() syscall in the kernel. The above excerpt continues from where the read syscall finished, showing the flow in user-land code in bash as it processed a keystroke, and prepared to read the next one.

While it’s a cute demo of DTrace functionality, I don’t use this feature that often. I’ve used it occasionally when the flow of a function was not obvious, for example, when function pointers are used and the source code doesn’t show which function names were called. The output can be many pages long, so I’ll usually write it to a text file and then read it using vi.

flow indent is cute but not hugely useful.

There are a few issues with flow indent: overhead, shuffling and entropy.

Overhead: Many functions were traced for the above example to work – 2407 probes. And this was just the functions from the bash segment (“pid$target:bash”). If I were to trace all functions in the program (including library functions), there would be thousands more. Tracing so much adds CPU overhead to the execution of the program, and can slow it down significantly (not just from the probe execution, but also from producing this much text output). If there is no other way to get this data, then the overhead may be worth the cost.

When I do use this, I’m careful to not leave it running too long to minimize the affect on performance. It can also produce too much output than is really needed, anyway. I solve these by limiting the time spent tracing, such as by using an “{ exit(0); }” action in a certain probe or in a timed probe (eg, profile:::tick-100ms).

Shuffling: The output can be shuffled on multi-CPU systems, since DTrace buffers output data per-CPU and periodically collects and prints these buffers without recombining them. (The rate can be tuned via the switchrate tunable, which defaults to once per second.) To work around this, I’ll add an action that includes a timestamp (eg, “{ trace(timestamp); }”), so that the output can be saved to a file and post-sorted. Having timestamps in the output is useful for another reason – locating the source of latency for performance analysis.

Entropy: Sometimes when you use flow indent, you’ll notice the flow moving to the right and not returning:

  0        -> memset
  0          -> memset
  0            -> mbrtowc
  0              -> pthread_getspecific
  0              <- pthread_getspecific
[...]
  0                    -> mbrtowc
  0                      -> pthread_getspecific
  0                      <- pthread_getspecific
[...]
  0                          -> mbrtowc
  0                            -> pthread_getspecific
  0                            <- pthread_getspecific
[...]
  0                                    -> mbrtowc
  0                                      -> pthread_getspecific
  0                                      <- pthread_getspecific

If you look closely, you may spot what is amiss - some functions are not returning (missing their "<-" returns), leaving whitespace entropy that pushes the indent further and further to the right. And in the above output, we've entered mbrtowc() four times (and it's not a recursive function).

The problem here wasn't that the return probe didn't fire, but that the return probe doesn't exist in the first place:

# dtrace -ln 'pid$target::mbrtowc:entry' -p 670
   ID   PROVIDER            MODULE                          FUNCTION NAME
148363     pid670 libSystem.B.dylib                           mbrtowc entry
# dtrace -ln 'pid$target::mbrtowc:return' -p 670
   ID   PROVIDER            MODULE                          FUNCTION NAME
dtrace: failed to match pid670::mbrtowc:return: No probe matches description

Missing Returns

The previous example showed that the pid provider has made an entry probe available for a certain function, but is missing its return probe. This can happen when DTrace struggles to instrument a complex function, such as one that contains a jump table added by the compiler as an optimization. Jump tables blur the line between data and instructions, making it difficult for DTrace to dissassemble the instructions to determine where the returns are. Another compiler optimization that can confuse DTrace is tail-call optimization, where a function can return to its grandparent directly, instead of a return to a parent that simply then returns to its parent (also can save a stack frame). Since it skips a return, the return probe does not fire.

Sometimes return probes don’t exist, or don’t fire.

Hopefully you won’t lose too many return probes, and have enough (along with the entry probes) to fetch the data you need.

You’ll notice the difference with probe counts. Here is Firefox on Mac OS X:

# dtrace -ln 'pid$target:::entry' -p 210 | wc -l
  256599
# dtrace -ln 'pid$target:::return' -p 210 | wc -l
  250972

That shows we are missing 2% of the return probes. Still, with a total probe count around 500,000, hopefully we can still get what we need.

If the missing return probes are a real problem and the software can be recompiled and redeployed, then compiling with a lower optimization level is likely to bring many of the missing probes back.

Compiler optimization can sometimes cause return probes to be missing.

The worst case I’ve seen was an application compiled 64-bit with Sun Studio 12.2, where 25% of the return probes were missing due to optimization. Usually it’s only about 2% of probes, and I’ve worked around it by picking other available probe points.

Return Probe Stability

The stability for return probes follows the stability of the entry names, as discussed in my first pid provider post. In summary: since this is the pid provider and is exposing application functions, nothing is guaranteed to be stable. This means that while your script may work fine on one version of an application, it may not work at all on the next because the function names and return values from functions may have changed. And, they could change in subtle ways (silent failure).

Given that return probes may also vanish due to compiler optimizations, your scripts may stop working due to an update in the compiler, not just an update in the target application.

Summary

The pid provider provides function return probes. These allow us to examine the return value and follow the code path, as demonstrated here. There are more limitations to be aware of with the return probe than the entry probe; apart from the stability and performance effect, certain return probes may not be available due to compiler optimizations.

Print Friendly
Posted on February 14, 2011 at 9:24 am by Brendan Gregg · Permalink
In: DTrace · Tagged with: ,

One Response

Subscribe to comments via RSS

  1. [...] This post was mentioned on Twitter by Deirdré Straughan, Brendan Gregg. Brendan Gregg said: I wrote another DTrace pid provider post, to explain the return probe http://bit.ly/eqvaas more new stuff [...]

Subscribe to comments via RSS