How to fix error on enabled probe: invalid address (0x0)?

I've the following error:

dtrace: error on enabled probe ID 3 (ID 7343: php15810:php:dtrace_execute_ex:function-return): invalid address (0x0) in action #2 at DIF offset 24

when I'm trying to trace my PHP script (sudo ./trace-php.d).

Basically what I wanted to achieve is to display distribution time/count by PHP function. It seems to work, but I'm annoyed by this error. I know I can send it to /dev/null, but I'd like understand and fix it.

Here is my dtrace code:

#!/usr/sbin/dtrace -Zs
#pragma D option quiet
php*:::function-entry
{
    self->vts = timestamp;
    self->cmd = arg0
}

php*:::function-return
/self->vts/
{
    @time[copyinstr(self->cmd)] = quantize(timestamp - self->vts);
    @num = count();
    self->vts = 0;
    self->cmd = 0;
}

profile:::tick-2s
{
  printf("\nPHP commands/second total: ");
  printa("%@d; commands latency (ns) by pid & cmd:", @num);
  printa(@time);
  clear(@time);
  clear(@num);
}

Sample output (while running some php script) is:

dtrace: error on enabled probe ID 3 (ID 7343: php15810:php:dtrace_execute_ex:function-return): invalid address (0x0) in action #2 at DIF offset 24
dtrace: error on enabled probe ID 3 (ID 7343: php15810:php:dtrace_execute_ex:function-return): invalid address (0x0) in action #2 at DIF offset 24
dtrace: error on enabled probe ID 3 (ID 7343: php15810:php:dtrace_execute_ex:function-return): invalid address (0x0) in action #2 at DIF offset 24
dtrace: error on enabled probe ID 3 (ID 7343: php15810:php:dtrace_execute_ex:function-return): invalid address (0x0) in action #2 at DIF offset 24

PHP commands/second total: 1549; commands latency (ns) by pid & cmd:
  variable_get                                      
           value  ------------- Distribution ------------- count    
            1024 |                                         0        
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4        
            4096 |@@@@@@@                                  1        
            8192 |@@@@@@@                                  1        
           16384 |                                         0        

  __construct                                       
           value  ------------- Distribution ------------- count    
            1024 |                                         0        
            2048 |@@@@@@@@@@@@@@@@@@@@                     3        
            4096 |@@@@@@@@@@@@@                            2        
            8192 |@@@@@@@                                  1        
           16384 |                                         0        

  features_array_diff_assoc_recursive               
           value  ------------- Distribution ------------- count    
           16384 |                                         0        
           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
           65536 |                                         0        

  features_export_info                              
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        122      
            8192 |@@@@@@                                   23       
           16384 |@                                        4        
           32768 |                                         0

Solution

This will likely do what you want, by breaking up the php*:::function-return probe into different clauses - one for whether you want to print the output or not (based on whether the argument is or isn't defined), and the second to clear up your thread local variables regardless of what you did or didn't do in the first probe clause.

This takes advantage of the fact that DTrace executes code for each probe in the exact order you define the clauses.

This example also uses a unique key combination of the probefunc and thread id (tid) for your self variables, so you don't accidentally overwrite these thread local variables as you descend into function calls:

#!/usr/sbin/dtrace -Zs

#pragma D option quiet

php*:::function-entry
{
    self->vts[tid,probefunc] = timestamp;
    self->cmd[tid,probefunc] = arg0
}

php*:::function-return
/self->vts[tid,probefunc] && self->cmd[tid,probefunc]/
{
    @time[copyinstr(self->cmd[tid,probefunc])] =
      quantize(timestamp - self->vts[tid,probefunc]);
    @num = count();
}

php*:::function-return
/self->vts[tid,probefunc]/
{
    self->vts[tid,probefunc] = 0;
    self->cmd[tid,probefunc] = 0;
}

profile:::tick-2s
{
  printf("\nPHP commands/second total: ");
  printa("%@d; commands latency (ns) by pid & cmd:", @num);
  printa(@time);
  clear(@time);
  clear(@num);
}

The above may not work well if any of the PHP functions have been Tail Call Optimized. To see if you're subject to this condition, run this:

#!/usr/sbin/dtrace -s

#pragma D option quiet

php*:::function-entry
{
  @e[probefunc,probename] = count();
}

php*:::function-return
{
  @r[probefunc,probename] = count();
}

tick-10sec
{
  printf("ENTRY POINTS\n");
  printa(@e);

  printf("RETURN POINTS\n");
  printa(@r);

  exit(0);
}

Sort the entry and return points - the counts don't have to match exactly, but you want every single probe function and name combination to have a match between the entry and return points. Be particularly wary of any that don't have a return point listed. Those are most likely Tail Call Optimized and you'll want to exclude those from your analysis, as you can never time them.