Enriching Trace with Call Stacks

I developed a little DTrace script which captures the call stack whenever a line containing a predefined string gets written into the trace file.

#!/usr/sbin/dtrace

/*

(c) 2018 Nenad Noveljic All Rights Reserved

Usage: dtrace -p PID -s call_stack_trace.d '"STRING"'

WARNING:  The script can dramatically slow down the observed process!!!

*/

#pragma D option quiet

syscall::write:entry
/ 
  pid == $target && 
  strstr(fds[arg0].fi_pathname,".trc") != 0  && 
  strstr(copyinstr(arg1),$1) != 0  
/
{
  printf("\n\n%s",copyinstr(arg1));
  ustack();
}

Although this script is generic and can be used with any software, I originally wrote it to understand which Oracle C functions are participating in a particular query transformation.

Its usage is trivial: to begin with, turn on the optimizer trace and then invoke the script as follows to get the call stacks for, for example, the join predicate push-down (JPPD) transformation:

dtrace -p PID -s call_stack_trace.d '"JPPD:"'

You can see the sample output below:

JPPD: Performing join predicate push-down (final phase) from query block SEL$A1EEA789 (#1) to query block SEL$2 (#2)

libc.so.1`__write+0xa
a.out`sdbgrfuwf_write_file+0x46
a.out`sdbgrfwf_write_file+0x3a
a.out`dbgtfdFileWrite+0x28c
a.out`dbgtfdFileAccessCbk+0x154
a.out`dbgtfWriteRec+0x529
a.out`dbgtRecVAWriteDisk+0xad
a.out`dbgtGrpBVaList_int+0xd8b
a.out`dbgtGrpB_int+0x9d
a.out`kkqjpdpvpd+0x1cec
a.out`kkqjpdpdp+0x320
a.out`kkqjpdctr+0x4b3			  
a.out`qksqbApplyToQbcLoc+0x256
a.out`qksqbApplyToQbc+0x34
a.out`kkqjpddrv+0x199
a.out`kkqdrv+0x1f53
a.out`kkqctdrvIT+0x3e3
a.out`apadrv+0xcba
a.out`opitca+0x966
a.out`kksFullTypeCheck+0x4c

The functions containing “dbg” in their names are just some low-level debugging functions for writing the output into the trace file.

The functions actually doing the JPPD transformation are the ones with “jpd” in their name.

Similarly, below is a captured stack for the OR-Expansion (ORE) transformation:

dtrace -p PID -s call_stack_trace.d '"ORE:"'

ORE: # conjunction chain - 3

libc.so.1`__write+0xa
a.out`sdbgrfuwf_write_file+0x46
a.out`sdbgrfwf_write_file+0x3a
a.out`dbgtfdFileWrite+0x28c
a.out`dbgtfdFileAccessCbk+0x154
a.out`dbgtfWriteRec+0x529
a.out`dbgtRecVAWriteDisk+0xad
a.out`dbgtTrcVaList_int+0xa0f
a.out`dbgtTrc_int+0xa6
a.out`kkqoreGetDNFCount+0xb11
a.out`kkqoreInitStateSpace+0x214
a.out`kkqctiss+0x408
a.out`kkqctdrvORE+0x13e
a.out`kkqoregdtr+0x94
a.out`qksqbApplyToQbcLoc+0x256
a.out`qksqbApplyToQbc+0x34
a.out`kkqctdrvTD+0x570
a.out`kkqoredrv+0x4a
a.out`kkqdrv+0xf35

As you can see, there are indeed a couple of functions containing “ore” in their name.

In conclusion, the DTrace script above provides the call stacks and hence a clue for further analysis.

After getting the functions names, I usually go to Frits Hooglands’ Oracle C functions annotations for more information.