Tuesday, May 11, 2010

Timing improvements in Oracle 11GR2 trace

I've been doing some research recently (I might blog about it a bit later if something worthwhile comes out of it) which resulted in a byproduct I found interesting to blog about.

In a nutshell, in one of the steps I've run the following PL/SQL block to trace the results of a very tight loop:
begin
dbms_monitor.session_trace_enable(waits => false, binds => false);
for i in 1 .. 100000
loop
for cur in (select null from dual)
loop
null;
end loop;
end loop;
dbms_monitor.session_trace_disable;
end;

While comparing raw trace files between 11.1.0.7 and 11.2.0.1 I've noticed something interesting. Here is an excerpt from 11.1.0.7 raw trace:
PARSING IN CURSOR #2 len=21 dep=1 uid=54 oct=3 lid=54 tim=1273621434711518
hv=2339989301 ad='86044a88' sqlid='bg2ng0u5rkttp'
SELECT NULL FROM DUAL
END OF STMT
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1273621434711518
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1273621434711518
CLOSE #2:c=0,e=0,dep=1,type=3,tim=1273621434711518
Notice how tim= values are the same across parse, exec, fetch and close; and e= values are zero for fetch, close and execute.

Now take a look at a similar excerpt from 11GR2:
PARSING IN CURSOR #3 len=21 dep=1 uid=57 oct=3 lid=57 tim=1273621440328909
hv=2339989301 ad='844d5a20' sqlid='bg2ng0u5rkttp'
SELECT NULL FROM DUAL
END OF STMT
EXEC #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1273621440328908
FETCH #3:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1273621440328947
CLOSE #3:c=0,e=1,dep=1,type=3,tim=1273621440328968
Notice how tim= value changes from line to line and e= has a corresponding value associated with it.

Before we move on you may ask how 11.1.0.7 calculates the time if all the values appear to be zero? The answer is that every so often you'll see a line like that:
FEXEC #5:c=1000,e=20960,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1273621434873334
Sure we didn't spent that much time fetching a single row. This value comes from the fact that we've just dumped all the time associated with multiple executions in this single line.

Now for 11GR2 to calculate the time with that additional precision will require a heck more times syscalls. To confirm this I've ran strace for processes in both 11GR1 and 11GR2 and here is what I came up with:

11GR1
[oracle@ora11gr1 tmp]$ grep -c times 4279.out
116
11GR2
[oracle@ora11gr2 tmp]$ grep -c times 5318.out
200149
Indeed, 11GR2 end up calling times twice per iteration while 11GR1 was doing one call per about thousand iterations. In total 11GR2 end up doing roughly 200K more syscalls. Next I became curious about how much overhead all these additional syscalls introduce and in order to find out I've run a small program:
[oracle@ora11gr2 tmp]$ cat do_times.c
#include

int main()
{
int i;
struct tms t;
clock_t c;
for (i=1;i<=200000;i++)
{
c=times(&t);
}

return 0;
}
[oracle@ora11gr2 tmp]$ gcc do_times.c
[oracle@ora11gr2 tmp]$ time ./a.out

real 0m0.096s
user 0m0.037s
sys 0m0.059s
We're talking about 0.01 second for 200K times syscalls, in other words - not much.

It's definitely nice to see all these small improvements being done.

No comments:

Post a Comment

Post a Comment