Tag Archives: oracle

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.

Full script:

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.