Craig Shallahamer wrote excellent article “When is v$sesstat really updated?”.
And my today post just a little addition and correction about the difference of updating ‘Db time’ and ‘CPU used by this session’ statistics.
Test #1
In this test I want to show that the statistics will be updated after every fetch call.
I have set arraysize=2, so sql*plus will fetch by 2 rows:
(full script)
-- Result will be fetched by 2 rows:
set arraysize 2;
-- this query generates CPU consumption
-- in the scalar subquery on fetch phase,
-- so CPU consumption will be separated
-- into several periods between fetch calls:
with gen as (
select/*+ materialize */
level n, lpad(level,400) padding
from dual
connect by level<=200
)
,stat as (
select/*+ inline */
sid,name,value
from v$mystat st, v$statname sn
where st.statistic#=sn.statistic#
and sn.name in ('DB time'
,'CPU used by this session'
,'user calls'
,'recursive calls')
)
--first rows just for avoiding SQL*Plus effect with fetching 1 row at start,
-- others will be fetched by "arraysize" rows:
select null rn,null cnt,null dbtime,null cpu,null user_calls, null recursive_calls from dual
union all -- main query:
select
rownum rn
,(select count(*) from gen g1, gen g2, gen g3 where g1.n>g2.n and g1.n*0=main.n*0) cnt
,(select value from stat where sid*0=n*0 and name = 'DB time' ) dbtime
,(select value from stat where sid*0=n*0 and name = 'CPU used by this session' ) cpu
,(select value from stat where sid*0=n*0 and name = 'user calls' ) user_calls
,(select value from stat where sid*0=n*0 and name = 'recursive calls' ) recursive_calls
from gen main
where rownum<=10;
set arraysize 15;
Test results:
SQL> @tests/dbtime
RN CNT DBTIME CPU USER_CALLS RECURSIVE_CALLS
---------- ---------- ---------- ---------- ---------- ---------------
1 3980000 12021 11989 200 472
2 3980000 12021 11989 200 472
3 3980000 12121 12089 201 472
4 3980000 12121 12089 201 472
5 3980000 12220 12186 202 472
6 3980000 12220 12186 202 472
7 3980000 12317 12283 203 472
8 3980000 12317 12283 203 472
9 3980000 12417 12383 204 472
10 3980000 12417 12383 204 472
As you can see the statistics are updated after every fetch call.
Test #2
Now since we already tested simple sql query, I want to do a little bit more complicated test with PL/SQL:
I’m going to write single PL/SQL block with next algorithm:
1. Saving stats
2. Executing some pl/sql code with CPU consumption
3. Getting statistics difference
4. Starting query from first test
5. Fetch 10 rows
6. Getting statistics difference
7. Fetch next 10 rows
8. Getting statistics difference
9. Fetch next 10 rows
10. Getting statistics difference
And after executing this block, i want to check statistics.
set feed off;
-- saving previous values
column st_dbtime new_value prev_dbtime noprint;
column st_cpu_time new_value prev_cputime noprint;
column st_user_calls new_value prev_user_calls noprint;
column st_recur_calls new_value prev_recur_calls noprint;
select max(decode(sn.NAME,'DB time' ,st.value))*10 st_dbtime
,max(decode(sn.NAME,'CPU used by this session' ,st.value))*10 st_cpu_time
,max(decode(sn.NAME,'user calls' ,st.value)) st_user_calls
,max(decode(sn.NAME,'recursive calls' ,st.value)) st_recur_calls
from v$mystat st, v$statname sn
where st.statistic#=sn.statistic#
and sn.name in ('DB time','CPU used by this session'
,'user calls','recursive calls'
)
/
-- variable for output from pl/sql block:
var output varchar2(4000);
prompt Executing test...;
----- main test:
declare
cnt int;
st_dbtime number;
st_cpu_time number;
st_user_calls number;
st_recur_calls number;
cursor c is
with gen as (select/*+ materialize */
level n, lpad(level,400) padding
from dual
connect by level<=200)
select
rownum rn
, (select count(*) from gen g1, gen g2, gen g3 where g1.n>g2.n and g1.n*0=main.n*0) cnt
from gen main
where rownum<=60;
type ctype is table of c%rowtype;
c_array ctype;
procedure SnapStats(descr varchar2:=null)
is
st_new_dbtime number;
st_new_cpu_time number;
st_new_user_calls number;
st_new_recur_calls number;
begin
select max(decode(sn.NAME,'DB time' ,st.value))*10 st_dbtime
,max(decode(sn.NAME,'CPU used by this session',st.value))*10 st_cpu_time
,max(decode(sn.NAME,'user calls' ,st.value)) st_user_calls
,max(decode(sn.NAME,'recursive calls' ,st.value)) st_recur_calls
into st_new_dbtime,st_new_cpu_time,st_new_user_calls,st_new_recur_calls
from v$mystat st, v$statname sn
where st.statistic#=sn.statistic#
and sn.name in ('DB time','CPU used by this session'
,'user calls','recursive calls'
);
if descr is not null then
:output:= :output || descr ||':'||chr(10)
|| 'sesstat dbtime: ' || (st_new_dbtime - st_dbtime )||chr(10)
|| 'sesstat cputime: ' || (st_new_cpu_time - st_cpu_time )||chr(10)
|| 'sesstat user calls: ' || (st_new_user_calls - st_user_calls )||chr(10)
|| 'sesstat recur calls:' || (st_new_recur_calls - st_recur_calls )||chr(10)
|| '======================================'||chr(10);
end if;
st_dbtime := st_new_dbtime ;
st_cpu_time := st_new_cpu_time ;
st_user_calls := st_new_user_calls ;
st_recur_calls := st_new_recur_calls;
end;
begin
-- saving previous stats:
SnapStats;
-- generating cpu load:
for i in 1..1e7 loop
cnt:=cnt**2+cnt**1.3-cnt**1.2;
end loop;
-- getting new stats:
SnapStats('After pl/sql loop');
open c;
SnapStats('After "open c"');
fetch c bulk collect into c_array limit 10;
SnapStats('After fetch 10 rows');
fetch c bulk collect into c_array limit 10;
SnapStats('After fetch 20 rows');
fetch c bulk collect into c_array limit 10;
SnapStats('After fetch 30 rows');
close c;
SnapStats('After close c');
end;
/
prompt 'Delta stats after statement(ms):';
select max(decode(sn.NAME,'DB time' ,st.value))*10
- &&prev_dbtime as delta_dbtime
,max(decode(sn.NAME,'CPU used by this session',st.value))*10
- &&prev_cputime as delta_cpu_time
,max(decode(sn.NAME,'user calls' ,st.value))
- &&prev_user_calls as delta_user_calls
,max(decode(sn.NAME,'recursive calls' ,st.value))
- &&prev_recur_calls as delta_recur_calls
from v$mystat st, v$statname sn
where st.statistic#=sn.statistic#
and sn.name in ('DB time','CPU used by this session'
,'user calls','recursive calls'
)
/
prompt 'Test results:';
col output format a40;
print output;
set feed off;
Output:
SQL> @tests/dbtime2
Executing test...
'Delta stats after statement(ms):'
DELTA_DBTIME DELTA_CPU_TIME DELTA_USER_CALLS DELTA_RECUR_CALLS
------------ -------------- ---------------- -----------------
18530 18460 5 33
Test results:
OUTPUT
----------------------------------------
After pl/sql loop:
sesstat dbtime: 0
sesstat cputime: 4350
sesstat user calls: 0
sesstat recur calls:2
======================================
After "open c":
sesstat dbtime: 0
sesstat cputime: 20
sesstat user calls: 0
sesstat recur calls:4
======================================
After fetch 10 rows:
sesstat dbtime: 0
sesstat cputime: 4680
sesstat user calls: 0
sesstat recur calls:2
======================================
After fetch 20 rows:
sesstat dbtime: 0
sesstat cputime: 4680
sesstat user calls: 0
sesstat recur calls:2
======================================
After fetch 30 rows:
sesstat dbtime: 0
sesstat cputime: 4690
sesstat user calls: 0
sesstat recur calls:2
======================================
After close c:
sesstat dbtime: 0
sesstat cputime: 0
sesstat user calls: 0
sesstat recur calls:3
======================================
We can notice that “CPU time” is updated at the same time as recursive calls, but “DB time” is updated only with “User calls”. Although this difference is not so important(because in most cases we can use other statistics in sum), but i think, if you want to instrument some code, it gives reason to check out desirable statistics for update time.