db time
- From: "Henry Poras" <henry@xxxxxxxxxxxxxxx>
- To: <oracle-l@xxxxxxxxxxxxx>
- Date: Tue, 14 Nov 2006 15:12:04 -0500
I've been looking at 'DB Time' and 'DB CPU' to try and get a better
feel for what information is in the numbers. Part of my curiousity came
from seeing similarly named variables in multiple locations (i.e.
v$sysstat, v$sys_time_model, ...). Are they all identical or not? So far
I have tracked down some of the answers, but am still working on a few
other questions. This is what I have so far (run on a 10.1.0.2 db).
I set up three tests.
The unit of work I used is roughly
CREATE TABLE big ...;
BEGIN
for i in 1 .. 100 loop
for x in (SELECT * FROM dba_objects) loop
insert into big values (x.field1, x.field2);
end loop;
end loop;
END;
/
DELETE FROM big;
DROP TABLE big;
I looked at the following stats:
sysdate
v$sesstat ('DB time')
v$sysstat ('DB time')
v$sess_time_model ('DB time')
v$sess_time_model ('DB CPU')
v$sys_time_model ('DB time')
v$sys_time_model ('DB CPU')
10046 trace file
elapsed time measured from beginning to end of trace file using tim
sum of non-recursive 'e' (elapsed time)
sum of non-recursive 'c' (cpu time)
sum of all 'ela' (wait times)
I ran the following three tests:
1. single session doing standard workload
2. two concurrent sessions running similar workloads (inserted into
big_1 and big_2)
3. single session with interspersed idle time (added sleeps in between
my two loops)
Each test started with taking a snapshot of the above stats, started a
10046 trace, ran the workload, took another snapshot, stopped the trace.
I then calculated the diffs between the snapshots.
This is what I found so far.
Run #1 Run #2 Run
#3
sysdate 442 s 723 s 632
s
v$sesstat(db time) 442 s 724 s 632
s
v$sysstat(db time) 874 s 2182 s 1310
s
v$sess_time_model(db_time) 432 s 707 s 418
s
v$sys_time_model(db_time) 434 s 1409 s 421
s
v$sess_time_model(db cpu) 362 s 460 s 354
s
v$sys_time_model(db cpu) 362 s 920 s 354
s
10046
tim(final) - tim(i) 431 s 707 s 617
s
e 432 s 596 s 617
s
c 362 s 448 s 360
s
ela 56 s 209 s 262
s
unaccounted for time 14 s -61 s -5
s
COMMENTS & QUESTIONS:
Run #1 was pretty much as expected except for v$sysstat. All other values
matched
up. Since there was only one session running on the system, sess and sys
values
for 'db time' and 'db cpu' matched. The trace file is also in line with the
rest
of the values. The only question is what is in v$sysstat? Does this include
bg
processes? Guess I'll check that out later.
Run #2
I expected the system data to be about twice as large as the session data as
there
are two sessions running concurrently. Again, except for v$sysstat, that is
what I
found. There is also reasonable correlation between different measures of
session data.
However, in this case, the trace file data is less clear. The elapsed time
measured
from tim matches the v$ table measured 'db time', and the cpu times match.
But the
measured elapsed time from the 10046 trace ('e') is about 100 seconds less
than
expected. Also, why did the cpu time/session jump from 360 to 460 seconds
from run #1
to run #2. I would expect elapsed time to increase, not the cpu necessary to
do the work.
Run #3
We now see that sysdate and v$sesstat measure wall clock time, while
sess_time_model
measures (as the documentation states) time spent performing DB calls not
including
background processes (and idle time waits). Sys and sess again match up, cpu
time/session
is similar to run #1, and the trace file numbers match the v$ tables.
So v$sesstat ('db time') <> v$sess_time_model('db time'). It is unclear what
v$sysstat('db time')
measures. The trace file seemed to lose 100 seconds in run #2.
Henry
Other related posts:
