Database Call CPU Instrumentation

In the previous blog post I provided the DTrace script for measuring wait event durations in Oracle database. This installment is about exploring how the CPU time is instrumented within a database call, like fetch and exec. Also here, I’m using Oracle 12.2.0.1.180116 database on Solaris 11.3.

First of all, immediately before start and after the completion of a database call, the Oracle function slcpums is called. The sole purpose of this function is to return the total CPU time that the thread has consumed so far.

By the way, the operating system implementation determines which OS kernel functions are underpinning slcpums. For example, on Oracle Solaris OS it is _lwp_info which fills the lwpinfo buffer. This buffer, in turn, contains user and system CPU time consumed by the thread.

Below is a captured stack for _lwp_info:

libc.so.1`_lwp_info
oracle`slcpums+0x21
oracle`opifch2+0x5c6
...

Secondly, if the SQL extended trace is on, Oracle database will execute the function kxstcol after finishing the database call. The purpose of this function is to prepare the information for tracing and then call the low level tracing functions. The CPU time captured at the database call start gets stored in a structure, precisely in its second 8 bytes. The pointer to this structure is passed as the first argument to kxstcol. The CPU time captured at the end of the database call is passed as the 6th parameter to the function kxstcol.

Last but not least, the function sdbgrfwf_write_file is a low-level tracing function which handles writing the information into the trace file. The pointer to the buffer containing the line that is to be written is passed as the 4th parameter.

Having said that, it’s not too difficult to come up with a DTrace script that tracks the execution of the CPU instrumentation calls:

#pragma D option quiet 

pid$target::opifch2:entry,
pid$target::opiexe:entry
{
  self->db_call = 1 ;
}

pid$target::opifch2:return,
pid$target::opiexe:return
{
  self->db_call = 0 ;
}

pid$target::slcpums:return
/ self->db_call /
{
  printf("%s cpu time: %d\n",probefunc,arg1);
}

pid$target::kxstcol:entry
/ self->db_call /
{
  this->start = *(uint64_t *)copyin( arg0 + 0x8 , 8 ) ;
  printf("%s start: %d end: %d\n", probefunc, this->start, arg5);
  printf("%s difference: %d \n", probefunc, arg5 - this->start);
}

pid$target::sdbgrfwf_write_file:entry
/ 
  strstr(copyinstr(arg3),"FETCH") != 0 || \
  strstr(copyinstr(arg3),"EXEC") != 0
/
{
  printf("%s %s",probefunc, copyinstr(arg3));
  printf("-----------\n");
}

And the sample output is below:

slcpums cpu time: 1093116
slcpums cpu time: 1094163
kxstcol start: 1093116 end: 1094163
kxstcol difference: 1047
sdbgrfwf_write_file FETCH #18446604434613586664:c=1047,e=1059,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=3435362257,tim=17411587167743