Strange anomaly in Statspack report calculation

While implementing a chart view for my Mumbai tool that shows elapsed_time, cpu_time, etc. (y-axis) over snapshots date/time (x-axis) for the “top” SQLs during the analyzed period from historic Statspack data, I found an anomaly in how the Statspack report scripts that come with Oracle sum up times for SQL statements.

I wanted to check if my own SQL statements and calculations in them are correct, so I compared the results from a Statspack report with my own results and they simply didn’t match for some SQL statements.

Here’s an excerpt of a Statspack report for the interval 788 to 866:

...
Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:        788 15-Mar-11 07:00:01      527      52.3
  End Snap:        866 15-Mar-11 21:00:02      507      53.2
   Elapsed:              840.02 (mins)

....

    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    311.75            5      62.35    2.6    7701.24      49,941,169 3997063716
Module: ...
SELECT ...

...

    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    210.86          327       0.64    1.7     212.80     55,695,007  382737340

Module: .....
SELECT ....

So, this says, elapsed time for SQL 382737340 was 212.80 seconds and elapsed time for SQL 3997063716 was 7701.24 seconds .

Looking at the base data in perfstat.stats$sql_summary for SQL 382737340:

SELECT snap_id,
       old_hash_value,
       sql_id,
       elapsed_time,
       address
FROM   stats$sql_summary
where  old_hash_value = 382737340
       and snap_id >= 788
       and snap_id <= 866
order  by snap_id;

   SNAP_ID OLD_HASH_VALUE SQL_ID        ELAPSED_TIME ADDRESS         
---------- -------------- ------------- ------------ ----------------
       788      382737340 1gkz43pqahmab   2622215854 C0000001255828A0
       789      382737340 1gkz43pqahmab   2622215854 C0000001255828A0
       791      382737340 1gkz43pqahmab   2675765393 C0000001255828A0
       801      382737340 1gkz43pqahmab   2690655093 C0000001255828A0
       811      382737340 1gkz43pqahmab   2786860831 C0000001255828A0
       821      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       831      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       841      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       851      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       861      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       862      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       863      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       864      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       865      382737340 1gkz43pqahmab   2835015256 C0000001255828A0
       866      382737340 1gkz43pqahmab   2835015256 C0000001255828A0

15 rows selected

The elapsed time from snap 866 minus the elapsed time from snap 788 is: 2,835,015,256 – 2,622,215,854 = 212,799,402 which matches the 212.80 seconds that the report showed for this SQL statement.

Now for the SQL statement with old_hash_value 3997063716:

SELECT snap_id,
       old_hash_value,
       sql_id,
       elapsed_time,
       address
FROM   stats$sql_summary
where  old_hash_value=3997063716
       and snap_id >= 788
       and snap_id <= 866
order  by snap_id;

   SNAP_ID OLD_HASH_VALUE SQL_ID        ELAPSED_TIME ADDRESS         
---------- -------------- ------------- ------------ ----------------
       788     3997063716 9vy8d50gvyj46   1368952389 C000000132C35FD8
       789     3997063716 9vy8d50gvyj46   2718723074 C000000132C35FD8
       861     3997063716 9vy8d50gvyj46   1349618334 C000000132F85390
       862     3997063716 9vy8d50gvyj46   1367700951 C000000132F85390
       863     3997063716 9vy8d50gvyj46   2723747322 C000000132F85390
       864     3997063716 9vy8d50gvyj46   4400055275 C000000132F85390
       865     3997063716 9vy8d50gvyj46   6127740256 C000000132F85390
       866     3997063716 9vy8d50gvyj46   7701241750 C000000132F85390

8 rows selected

The elapsed time in the Statspack report was 7,701.24 seconds, which obviously matches the elapsed time for snap_id 866. Also note that the ADDRESS changes for snap_id 861.

So, the Statspack report seems to ignore the elapsed time that comes from the first cursor version for this SQL.
My expectation would be that the elapsed time between snap 788 and 789 (2,718,723,074 – 1,368,952,389 = 1,349,770,685 => 1,349.77 seconds) would be included in the total elapsed time for this SQL, giving a total of 9,051.01 seconds.

I haven’t tested this yet, but imagine a database with some long-running batch jobs running every night. The SQL statements for these batch jobs would age out of the shared pool due to the normal load over the day. What would be the elapsed times for the nightly batch SQL statements that we would see in a Statspack report for a full week? Just the times from the last run? I’ll probably test this soon…

This entry was posted in Mumbai. Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s