Generate statspack report for the most recent interval quickly

Sometime we need to generate most recent statspack report to understand the problem that have just happened. The script to generate statspack report is spreport.sql, usually we execute this script in SQL* Plus as follows:

SQL> @?/rdbms/admin/spreport

We then need to interactively input start and end snap ids and report name. It is not difficult to modify this script to accept these input variables at command line. For example I have a script called spreport_ds.sql located in my SQLPATH, which can be used in the following way:

SQL> @spreport_ds.sql

The relevent modifications in my spreprot_ds.sql script are shown as follows:

prompt
-- prompt Specify the Begin and End Snapshot Ids
-- prompt ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
-- prompt Begin Snapshot Id specified: &&begin_snap
-- prompt
-- prompt End   Snapshot Id specified: &&end_snap
prompt

define begin_snap = &1
define end_snap = &2

--
--  Set up the snapshot-related binds, and additional instance info

set termout off;

variable bid        number;
variable eid        number;
begin
  :bid       :=  &&begin_snap;
  :eid       :=  &&end_snap;
end;
/

prompt
-- prompt Specify the Report Name
-- prompt ~~~~~~~~~~~~~~~~~~~~~~~
-- prompt The default report file name is &dflt_name..  To use this name,
-- prompt press  to continue, otherwise enter an alternative.

set heading off;
column report_name new_value report_name noprint;
-- select 'Using the report name '  nvl('&&report_name','&dflt_name')
--     , nvl('&&report_name','&dflt_name') report_name
--   from sys.dual;

define report_name = &3
spool &report_name;
set heading on;
prompt

With this modified script in place, I created another script called sp_mrti.sql to generate statspack report for the most recent interval:

----- script: sp_mrti.sql -----------------
rem sp_mrti.sql
rem  -- generate a statspack report for the  most recent time interval
rem
rem  dependent:  spreport_ds.sql
rem

col eid new_val eid
col sid new_val sid
select max(snap_id)  eid,
       max(snap_id) - 1 sid
from perfstat.stats$snapshot
;

col stime new_val stime
col etime new_val etime

select  to_char(snap_time, 'YYYYMMDD_HH24MI') stime
from perfstat.stats$snapshot
where snap_id = &sid;


select  to_char(snap_time, 'HH24MI') etime
from perfstat.stats$snapshot
where snap_id = &eid;

col instname new_val instname
select instance_name instname from v$instance;


@spreport_ds &sid &eid  &instname._&stime._&etime..txt

----- end of script: sp_mrti.sql ----------

Discovering the I/O pattern of a production database through mining STATSPACK data

1. Total I/O in every hour during weekdays

Total I/O is defined as the number of physical reads plus the number of physical writes. They can be obtained throught the following two scripts, respectively.

----  Sample Script to obtain physical reads ---------
select
             to_char(sn.snap_time, 'YYYY-MM-DD HH24') start_time,
             sum(b.value - a.value)  val
        from perfstat.stats$sysstat a,
             perfstat.stats$sysstat b,
             perfstat.stats$snapshot sn
        where sn.snap_id = a.snap_id
        and   a.snap_id = b.snap_id -1
        and   a.statistic# = 42
        and   b.statistic# = 42
          and snap_time >= to_date('2009-01-26', 'YYYY-MM-DD')
          and snap_time < to_date('2009-01-31', 'YYYY-MM-DD')
        group by to_char(sn.snap_time, 'YYYY-MM-DD HH24')
;
----  END of Sample Script to obtain physical reads ---------

----  Sample Script to obtain physical writes---------

select
             to_char(sn.snap_time, 'YYYY-MM-DD HH24') start_time,
             sum(b.value - a.value)  val
        from perfstat.stats$sysstat a,
             perfstat.stats$sysstat b,
             perfstat.stats$snapshot sn
        where sn.snap_id = a.snap_id
        and   a.snap_id = b.snap_id -1
        and   a.statistic# = 46
        and   b.statistic# = 46
          and snap_time >= to_date('2009-01-26', 'YYYY-MM-DD')
          and snap_time < to_date('2009-01-31', 'YYYY-MM-DD')
        group by to_char(sn.snap_time, 'YYYY-MM-DD HH24')
;
----  END of Sample Script to obtain physical writes---------

2. Average Time Per Read (ATPR) in every hour during weekdays

In the Statspack report, there is a section called "Tablespace I/O Statistics", along with the "File I/O section" they can be used to identify whether I/O is especially slow or there are an exceptional number of I/Os on any specific data file or tablespaces. There is a field called "Av Rd (ms)", representing average time per read in milli-second. Generally speaking, 20ms - 40ms reads may be considered slow for single block reads. In this post, I used a script to count the number of tablespaces that have ATPR greater than 100ms.

----- Sample script to obtain the number of tablespaces
------ that have ATPR greater than 100ms
select mydate, sum(case when atpr_ms > 100 then 1 else 0 end)
from (
        select
             to_char(snap_time,'yyyy-mm-dd HH24') mydate,
             old.tsname,
             sum(new.phyrds-old.phyrds)   phy_rds,
             sum(new.phywrts-old.phywrts) phy_wrts,
             sum(new.readtim-old.readtim) read_tim,
             sum(new.writetim-old.writetim) write_tim,
             decode(sum(new.phyrds-old.phyrds), 0,0,
             sum(new.readtim-old.readtim) *10 / sum(new.phyrds-old.phyrds) ) atpr_ms
          from
             perfstat.stats$filestatxs old,
             perfstat.stats$filestatxs new,
             perfstat.stats$snapshot   sn
          where
             old.snap_id = sn.snap_id
          and
             old.filename = new.filename
          and
             new.snap_id = sn.snap_id + 1
          and
             (new.phyrds-old.phyrds) > 0
          and snap_time >= to_date('2009-01-26', 'YYYY-MM-DD')
          and snap_time < to_date('2009-01-31', 'YYYY-MM-DD')
          group by
             to_char(snap_time,'yyyy-mm-dd HH24'),
             old.tsname
        )
group by mydate
;

3. Grapth the I/O pattern:

Sample Graph - Total IO changes with every hour
Sample Graph - Average Time Per Read Count

AWK script to analyze statspack report

I have written a small awk script to help to analyze statspack report. The content of the script is as follows:

.

The content of the script is as follows:

$ cat printload.awk
{
  if ( $0 ~ /Load Profile/ ) {
     print "===>"  FILENAME
     print $0
     getline
     print $0
     getline
     print $0
     getline
     print $0
     getline
     print $0
   }
}


Here is an example of its usage:

$ awk -f printload.awk *_1114*.lst

===>sp_P1ROCCS_1114_00:00_01:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:           -530,710.25        -39,825,381.33
              Logical reads:              5,346.96            401,244.58
===>sp_P1ROCCS_1114_01:00_02:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            661,687.44         62,668,765.37
              Logical reads:              5,337.23            505,492.05
===>sp_P1ROCCS_1114_04:00_05:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:           -261,353.97            -16,558.50
              Logical reads:             34,913.84              2,212.02
===>sp_P1ROCCS_1114_05:00_06:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            679,480.45            635,181.85
              Logical reads:              9,648.79              9,019.74
===>sp_P1ROCCS_1114_06:00_07:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:           -531,582.88        -11,387,897.48
              Logical reads:              7,055.82            151,154.21
===>sp_P1ROCCS_1114_07:00_08:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            632,586.85         26,531,869.35
              Logical reads:              6,800.79            285,237.83
===>sp_P1ROCCS_1114_08:00_09:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:           -535,177.88        -18,857,150.16
              Logical reads:              6,451.35            227,315.36
===>sp_P1ROCCS_1114_09:00_10:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            657,449.22         15,364,673.58
              Logical reads:              5,490.71            128,318.66
===>sp_P1ROCCS_1114_10:00_11:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            542,321.35            648,839.10
              Logical reads:             14,599.49             17,466.99
===>sp_P1ROCCS_1114_11:00_12:03.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            268,331.93            319,353.99
              Logical reads:             19,272.63             22,937.23
===>sp_P1ROCCS_1114_12:03_13:07.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            316,435.43            342,552.49
              Logical reads:             22,151.92             23,980.23
===>sp_P1ROCCS_1114_14:00_15:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            149,285.73            391,643.98
              Logical reads:              6,620.19             17,367.75
===>sp_P1ROCCS_1114_15:00_16:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            158,509.15            256,437.01
              Logical reads:              7,857.87             12,712.51
===>sp_P1ROCCS_1114_16:00_16:58.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            197,935.84            243,677.31
              Logical reads:             10,099.65             12,433.60
===>sp_P1ROCCS_1114_16:58_17:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            799,700.92            948,216.80
              Logical reads:             37,202.29             44,111.29
===>sp_P1ROCCS_1114_17:00_18:00.lst
Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            541,252.15            441,183.58
              Logical reads:             26,538.76             21,632.18

I know under cygwin I can use grep -A option to achieve same goal.
I can do something as follows:
grep -A5 "Load Profile" *_1114*.lst

Note:
-A NUM, --after-context=NUM
Print NUM lines of trailing context after matching lines. Places a line
containing -- between contiguous groups of matches.

However, the version of grep on our server does not have this option.

statspack survival guide

http://www.akadia.com/services/ora_statspack_survival_guide.html

Lab: Using Statspack Under Oracle XE

1. Install - Run the create scripts (under Oracle 10g XE version)

SQL> connect / as sysdba
SQL> @C:\oraclexe\app\oracle\product\10.2.0\server\RDBMS\ADMIN>spcreate.sql

Notes: prompted for enter password (oracle), the default tablespace SYSAUX
       was chosed, the temporary tablespace was also chosen as TEMP

2. Adjusting the STATSPACK Collection Level

   STATSPACK has two types of collection options: level and threshold.
     level     - controls the type of data collected from Oracle
     threshold - as a filter for the collection of SQL statements into
                 the stats$sql_summary table

   To show the description of different level, issue the following statement:
   SQL> select * from stats$level_description order by snap_level;

   To change the level of a snapshot, you can use statspack.snap function.
   The i_modify_parameter=> 'true' changes the level permanent for all
   snapshots in the future. e.g.
   SQL> exec statspace.snap(i_snap_level => 6, i_modify_parameter => 'true');

3. Create, View and Delete Snapshots


SQL> connect perfstat/oracle
Connected.
SQL> exec statspack.snap
PL/SQL procedure successfully completed.


SQL> select name, snap_id, to_char(snap_time, 'MM-DD-YYYY:HH24:MI:SS')
  2  "Date/Time" from stats$snapshot, v$database;

NAME         SNAP_ID Date/Time
--------- ---------- -------------------
XE                 1 09-29-2006:15:03:40
XE                 2 09-29-2006:15:04:31
XE                11 09-29-2006:15:06:09

   
  
To delete
SQL> @?\rdbms\admin\sppurge;

Notes: prompted to enter low and high snapshot ID


4. Create the Report


SQL> @?\rdbms\admin\spreport.sql

Specify the Begin and End Snapshot Ids
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Enter value for begin_snap: 11
Begin Snapshot Id specified: 11

Enter value for end_snap: 21
End   Snapshot Id specified: 21

Specify the Report Name
~~~~~~~~~~~~~~~~~~~~~~~
The default report file name is sp_11_21.  To use this name,
press  to continue, otherwise enter an alternative.

Enter value for report_name:


5. Statspack at a Glance  - understading the report



5.1. Statspack Report Header

STATSPACK report for

Database    DB Id    Instance     Inst Num Startup Time    Release     RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
          2481462586 xe                  1 29-Sep-06 14:10 10.2.0.1.0  NO

Host  Name:   NTBK             Num CPUs:    1        Phys Memory (MB):      494
~~~~

Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:         11 29-Sep-06 15:06:09       16       5.4
  End Snap:         21 29-Sep-06 15:14:59       16       3.8
   Elapsed:                8.83 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:        72M             Std Block Size:         8K
           Shared Pool Size:        52M                 Log Buffer:     2,792K


Notes:
Curs/Sess column - shows the number of open cursors per session.
the item we are most interested in is the elapsed time. We want that to be
large enough to be meaningful, but small enough to be relevant (15 to 30
minutes is OK).

5.2 Statspack Load Profile

Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:              5,410.54            716,896.00
              Logical reads:                 71.40              9,460.25
              Block changes:                 33.27              4,408.75
             Physical reads:                  0.03                  4.50
            Physical writes:                  4.69                621.25
                 User calls:                  0.21                 28.25
                     Parses:                  6.08                805.50
                Hard parses:                  0.86                114.50
                      Sorts:                  3.84                509.25
                     Logons:                  0.01                  0.75
                   Executes:                 13.62              1,804.00
               Transactions:                  0.01

  % Blocks changed per Read:   46.60    Recursive Call %:    99.88
 Rollback per transaction %:    0.00       Rows per Sort:     6.65

Notes:
 Three items are important:
   - The Hard parses (we want very few of them)
   - Executes (how many statements we are executing per second/transaction
   - Transactions (how many transactions per second we process).

 This gives an overall view of the load on the server.
 a fairly light system load (1-4 transactions per second is low).

5.3 Statspack Instance Efficiency Percentage

Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.95    In-memory Sort %:  100.00
            Library Hit   %:   86.15        Soft Parse %:   85.79
         Execute to Parse %:   55.35         Latch Hit %:  100.00
Parse CPU to Parse Elapsd %:   77.17     % Non-Parse CPU:   68.03

 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   77.74   79.31
    % SQL with executions>1:   91.71   70.29
  % Memory for SQL w/exec>1:   98.44   90.15


Notes:

Most important: Library Hit, Soft Parse and Execute to Parse. All of these
have to do with how well the shared pool is being utilized.

If the library Hit ration was low, it could be indicative of a shared pool
that is too small, or just as likely, that the system did not make correct
use of bind variables in the applicaiton

OLTP System
   The Soft Parase % value is one of the most important ratio in the database.
   For a typical OLTP system, it should be as near to 100% as possible. You
   quite simply do not hard parse after the database has been up for a while
   in your typical transactional / general-purpose database. The way you
   achieve that is with bind variables.

Data Warehouse
   In a data warehouse, we would like to generally see the Soft Parse ratio
   lower. We don't necessarily want to use bind variables in a data warehouse.
   This is because they typically use materialized views, hustograms, and
   other things that are easily thwarted by bind variables. In a data warehouse,
   we may have many seconds between executions, so hard parsing is not evil;
   in fact, it is good in those environments


5.4 Statspack Top 5 Timed Events

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file parallel write                             487           7     15   45.7
CPU time                                                         6          37.4
log file parallel write                            116           1      9    6.5
control file parallel write                        177           1      4    4.8
control file sequential read                       247           1      3    3.8
          -------------------------------------------------------------


Notes:
  CPU time - the sum of the CPU used by this session, or the amount of CPU
             time used during the snapshot window. In a heavily loaded system,
             if the CPU time event is the biggest event, that could point to
             some CPU-intensive processing

5.5 SQL ordered by Gets

Here you will find the most CPU-Time consuming SQL statements