Getting information about previously run commands with statspack

cbruhn2's picture
articles: 

Information


When you setup statspack with level 6 you can have information on the sql_plan associated with a sql. (statpack on oracle db version >=9i)

Ways to setup level 6.


exec statspack.snap(i_snap_level => 6, i_modify_parameter => 'true');
EXECUTE STATSPACK.SNAP(i_snap_level=>6); <-- this is used if you want a one shot.
EXECUTE STATSPACK.MODIFY_STATSPACK_PARAMETER(i_snap_level => 6);

Normal info
When you run the statspack report (spreport) script you will get information like

                                                     CPU      Elapsd     Old
  Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
        299,980           11       27,270.9   33.5     6.51      7.68 2676219584
SELECT * FROM (SELECT /*+ ALL_ROWS MeasurementApprovalOptimizedV
O */ T0.OL_SAMPLE_ID AS F0, T0.OL_ORDINV_ID AS F1, T0.OL_MSR_STA
TUS AS F2, T0.OL_QCCID_ID AS F3, T0.OL_MSR_SUPPLIER_SMP_ID AS F4
, T0.OL_MSR_SUPPLIER_TEST AS F5, T0.OL_MSR_TIME AS F6, T0.OL_MSR
_RECEIVED_TIME AS F7, T0.OL_SPL_ID AS F8, T0.OL_MSR_IS_CONTROL A

From the report. Notice the value of Old Hash Value.

Additional information about the sql
The value of Old Hash Valus can be used to get more information about the sql, when running the script $ORACLE_HOME/admin/rdbms/sprepsql.sql as user perfstat.

SQL>connect perfstat/perfstat
SQL>@?/rdbms/admin/sprepsql
..... Now comes the normal list of statspack reports.

                                 35 06 Feb 2007 12:11     5
                                 36 06 Feb 2007 12:13     6
                                 37 06 Feb 2007 12:14     6



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

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



Specify the old (i.e. pre-10g) Hash Value
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Enter value for hash_value: 2676219584 <-- this was the value seen in the statspack report.
Hash Value specified is: 2676219584



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

Enter value for report_name:

Using the report name sp_36_37_2676219584


STATSPACK SQL report for Old Hash Value: 2676219584

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ----------------
PLAB           113542438 PLAB                1 10.1.0.4.0  NO  p570b1

 Start Id     Start Time         End Id      End Time       Duration(mins)
--------- ------------------- --------- ------------------- --------------
       36 06-Feb-07 12:13:47         37 06-Feb-07 12:14:19            0.53

SQL Statistics
~~~~~~~~~~~~~~
-> CPU and Elapsed Time are in seconds (s) for Statement Total and in
   milliseconds (ms) for Per Execute
                                                       % Snap
                     Statement Total      Per Execute   Total
                     ---------------  ---------------  ------
        Buffer Gets:         299,980         27,270.9   33.46
         Disk Reads:               0              0.0     .00
     Rows processed:             167             15.2
     CPU Time(s/ms):               7            591.9
 Elapsed Time(s/ms):               8            698.2
              Sorts:              11              1.0
        Parse Calls:               7               .6
      Invalidations:               0
      Version count:               3
    Sharable Mem(K):             195
         Executions:              11

SQL Text <-- Notice that full sql text is displayed
~~~~~~~~
SELECT * FROM (SELECT /*+ ALL_ROWS MeasurementApprovalOptimizedV
O */ T0.OL_SAMPLE_ID AS F0, T0.OL_ORDINV_ID AS F1, T0.OL_MSR_STA
TUS AS F2, T0.OL_QCCID_ID AS F3, T0.OL_MSR_SUPPLIER_SMP_ID AS F4
, T0.OL_MSR_SUPPLIER_TEST AS F5, T0.OL_MSR_TIME AS F6, T0.OL_MSR
_RECEIVED_TIME AS F7, T0.OL_SPL_ID AS F8, T0.OL_MSR_IS_CONTROL A
S F9, T0.OL_MSR_ALARM_STATUS AS F10, T0.OL_MSR_CORRECTED AS F11,
 T0.OL_MSR_TUBE_POSITION AS F12, T0.OL_MSR_INT_COMMENT AS F13, T
0.OL_MSR_COMMENT AS F14, T0.OL_FRML_ID AS F15, T0.OL_MSR_FLAG_SU
MMARY AS F16, T0.OL_MSR_FLAG_ACTION AS F17, T0.OL_MSR_RESULT AS
F18, T0.OL_MSR_REPLY AS F19, T0.OL_MSR_CALCULATION_TYPE AS F20,
T0.OL_RUN_ID AS F21, T0.OL_RUN2_ID AS F22, T0.OL_MSR_RESOLVED_SA
MPLE_ID AS F23, T0.OL_INVER_ID AS F24, T0.OL_MSR_DOUBLE_MSR AS F
25, T0.OL_MSR_STATE AS F26, T0.OL_MSR_GM AS F27, T0.OL_MSR_SHOW_
INSTR_SAMPLE_ID AS F28, T0.OL_MSR_MEASUREMENT_SET AS F29, T0.OL_
MSR_ID AS F30, T0.TS AS F31, T0.OL_UNIT_ID AS F32, T0.OL_RM_ID A
S F33, T1.OL_RUN_QC_FAILED AS F34, T1.OL_RUN_ACTION AS F35, T1.O
L_RUN_START_TIME AS F36, T1.OL_RUN_STATUS AS F37, T1.OL_SPLINV_I
D AS F38, T1.OL_RUN_ID AS F39, T1.TS AS F40, T2.OL_SOI_ID AS F41
, T2.OL_SAMPLE_SOI_TYPE AS F42, T2.OL_SAMPLE_NUMBER AS F43, T2.O
L_SAMPLE_EXT_COMM AS F44, T2.OL_SAMPLE_INT_COMM AS F45, T2.OL_SA
MPLE_START_TIME AS F46, T2.OL_HCPCDE_ID AS F47, T2.OL_SAMPLE_ID
AS F48, T2.TS AS F49, T3.OL_QCCID_ID AS F50, T3.TS AS F51, T3.CA
NCEL_TS AS F52, T4.OL_SOI_ID AS F53, T4.OL_SOITYPE_ID AS F54, T4
.OL_ORDINV_REPLY_WITHIN AS F55, T4.OL_ORDINV_EXPECTED_TIME AS F5
6, T4.OL_ORDINV_DEEPENING AS F57, T4.OL_MSR_ID AS F58, T4.OL_ORD
INV_ALARM_STATUS AS F59, T4.OL_ORDINV_DEEP_DONE AS F60, T4.OL_OR
DINV_REPLY_SEEN AS F61, T4.OL_ORDINV_LIST_ITEM AS F62, T4.OL_INV
_ID AS F63, T4.OL_ACTSTATE_ID AS F64, T4.OL_ORDINV_ID AS F65, T4
.TS AS F66, T4.CANCEL_TS AS F67, T4.OL_PRIORITY_ID AS F68 FROM O
L_MEASUREMENT T0 LEFT OUTER JOIN OL_RUN T1 ON T0.OL_RUN_ID=T1.OL
_RUN_ID LEFT OUTER JOIN OL_SAMPLE T2 ON T0.OL_SAMPLE_ID=T2.OL_SA
MPLE_ID LEFT OUTER JOIN OL_QC_CONTROL_ID T3 ON T0.OL_QCCID_ID=T3
.OL_QCCID_ID LEFT OUTER JOIN OL_ORDERED_INV T4 ON T0.OL_ORDINV_I
D=T4.OL_ORDINV_ID WHERE  T0.OL_WORKPLACE_ID = :1 AND T0.OL_SPL_I
D IN (:2) AND T0.OL_MSRTYPE = :3 AND NOT (T0.OL_MSR_STATUS IN (:
4, :5, :6, :7, :8, :9, :10, :11, :12, :13)) AND (T0.OL_MSR_DOUBL
E_MSR IS NULL OR T0.OL_MSR_DOUBLE_MSR=:14 OR T0.OL_MSR_DOUBLE_MS
R = :15 AND (T0.OL_MSR_STATE IS NULL OR T0.OL_MSR_STATE=:16)) AN
D (T0.OL_QCCID_ID IS NOT NULL OR T0.OL_ORDINV_ID IS NOT NULL OR
T0.OL_MSR_STATUS IN (:17, :18, :19)) AND (T0.OL_RUN_ID IS NULL O
R T1.OL_RUN_END_TIME IS NOT NULL) ORDER BY T0.OL_MSR_RECEIVED_TI
ME, T0.OL_MSR_SUPPLIER_SMP_ID, T0.OL_MSR_MEASUREMENT_SET, T0.OL_
INVER_ID) FOO WHERE ROWNUM <= 1001

Known Optimizer Plan(s) for this Old Hash Value
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Shows all known Optimizer Plans for this database instance, and the Snap Id's
they were first found in the shared pool.  A Plan Hash Value will appear
multiple times if the cost has changed
-> ordered by Snap Id

  First        First          Plan
 Snap Id     Snap Time     Hash Value        Cost
--------- --------------- ------------ ----------
       36 06 Feb 07 12:13   3841969555        12

Plans in shared pool between Begin and End Snap Ids
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Shows the Execution Plans found in the shared pool between the begin and end
snapshots specified.  The values for Rows, Bytes and Cost shown below are those
which existed at the time the first-ever snapshot captured this plan - these
values often change over time, and so may not be indicative of current values
-> Rows indicates Cardinality, PHV is Plan Hash Value
-> ordered by Plan Hash Value

--------------------------------------------------------------------------------
| Operation                      | PHV/Object Name     |  Rows | Bytes|   Cost |
--------------------------------------------------------------------------------
|SELECT STATEMENT                |----- 3841969555 ----|       |      |     12 |
|COUNT STOPKEY                   |                     |       |      |        |
| VIEW                           |                     |     1 |    6K|     12 |
|  SORT ORDER BY STOPKEY         |                     |     1 |  363 |     12 |
|   NESTED LOOPS OUTER           |                     |     1 |  363 |     11 |
|    NESTED LOOPS OUTER          |                     |     1 |  306 |      9 |
|     FILTER                     |                     |       |      |        |
|      NESTED LOOPS OUTER        |                     |     1 |  259 |      7 |
|       NESTED LOOPS OUTER       |                     |     1 |  204 |      5 |
|        TABLE ACCESS BY INDEX RO|OL_MEASUREMENT       |     1 |  189 |      4 |
|         INDEX RANGE SCAN       |OL_MSR_SPL_FK        |     1 |      |      3 |
|        TABLE ACCESS BY INDEX RO|OL_QC_CONTROL_ID     |     1 |   15 |      1 |
|         INDEX UNIQUE SCAN      |OL_QCCID_PK          |     1 |      |      0 |
|       TABLE ACCESS BY INDEX ROW|OL_RUN               |     1 |   55 |      2 |
|        INDEX UNIQUE SCAN       |OL_RUN_PK            |     1 |      |      1 |
|     TABLE ACCESS BY INDEX ROWID|OL_SAMPLE            |     1 |   47 |      2 |
|      INDEX UNIQUE SCAN         |OL_SAMPLE_PK         |     1 |      |      1 |
|    TABLE ACCESS BY INDEX ROWID |OL_ORDERED_INV       |     1 |   57 |      2 |
|     INDEX UNIQUE SCAN          |OL_ORDINV_PK         |     1 |      |      1 |
--------------------------------------------------------------------------------

End of Report

SQL>

Notice
If you run the sprepsql.sql script on level 5 reports you will only get the full sql text. So even if you don't get the explain plan, you will still be able to get more information about the sql when you use the script.

That's all folks.
Carl Bruhn

Comments

Is the ROWS column in the plan the ACTUAL rows processed? Or just the estimate as shown in AUTOTRACE. I was really excited there for a moment because I thought you'd found a way to get actual rows per plan step that is less tedious than TKPROF, but I suspect it is just the estimates pulled from V$SQL_PLAN.

I've never used StatsPack personally - never got out of the habit of TKPROF. Under what circumstances do you find it useful? My very rough understanding is that it's handy when you are unable to start a trace (or a trace file would be inconveniently large) or when you don't know which session is causing the problem and you want to look at everything thats running.


Ross Leishman

cbruhn2's picture

Hi Ross,

Instead of testing I checked the code in sprepins.sql.
It's just statistics from v$sql_plan that is gathered.

Best regards.
Carl Bruhn.

cbruhn2's picture

Hi Ross,

thank's for your comment.

I also suspect it's just the v$sql_plan as the buildup of all statspack is actually making a dump of information from v$ tables.
So I will make a small test (hasn't done yet) where I will use dbms_stats.set_table_stats with something like zillions of rows and billions of blocks, and then run my statspack report. (Comming soon to a theater near you :-)

About statspack versus tkprof.
I use to setup statspack at client sites to get information about what's going on DB-wise. It will keep me
- informed about the worst cases (sqls) (A lot of times its statspack :-).
- building baselines for perfmonace.
I use to set it up on databases running 15 mins periods and then clean out every week if nothing is reported from users/baseline.
This can all be done for free as statspack is part of the core database installation.
The new features of AWS (10g) is also part of the core, but you have to pay the license in order to use it. Statspacke can deliver at least some of the functionality of AWS.

For actually doing performance optimizing I haven't heard of anything that can beat 10046 trace (in different flavours)
Especially I think the new features in Oracle 10g for tracing web-apps., is very interesting. Unfortunatly the programmers has to build in 'marks' the application so tracefiles can be gathered for a specific module/program, and it seems that most doesn't do so. Perhaps a blog entry was appropriate about that.

best regards.
Carl Bruhn