Working with Oracle’s Time Model Data 3

9 02 2010

February 9, 2010

(Back to the Previous Post in the Series)

 In the previous article in this series, we created a structured view of the V$SYS_TIME_MODEL view:
 

Then on demand brought in session level detail for the same statistics so that it was possible to investigate why a statistic value continued to grow.  The previous article also displayed delta values from V$OSSTAT and the wait events from V$SYSTEM_EVENT.  It appears that a couple people liked the previous effort, and I gave serious thought to having the computer provide audio feedback when a session started consuming a lot of resources – but then I started to wonder if maybe we should instead have an audio warning when a session is consuming less than the average resource consumption so that we could then determine who is reading this article rather than working. :-)  In the end, I decided to leave out the audio feedback.  So, what else can we do with the framework that was provided in the second article of this series?

It might be nice to be able to drill into session-level wait events to determine why a wait event’s time delta keeps growing, maybe by adding a couple of extra buttons to the web page that is created on the fly by the VBS script:

It might also be nice to be able to view the DBMS_XPLAN for a query that was identified as a SQL statement that was recently executed by a session.  One of the problems with the original script is that it only retrieved the SQL_ID and SQL_CHILD_NUMBER from V$SESSION, and it seemed that those columns contained NULL values just as frequently as they contained data.  The updated script will attempt to return the PREV_SQL_ID and PREV_CHILD_NUMBER columns if the other two columns contain NULL values.  In addition to retrieving the DBMS_XPLAN for the CHILD_NUMBER that is executed by the session, it might also be helpful to retrieve the DBMS_XPLAN for all child cursors for a given SQL_ID so that we are able to determine if the execution plan changed, and why it changed.  While we are at it, let’s make it possible to enable a 10046 extended SQL trace for a session just by clicking a button on the web page.  With the changes to the script, the generated web page might look something like this (note that this is a touched up image – the computer name and username were erased):

Scrolling down to the bottom of the page, note that the Session Waits button for the db file scattered read wait event was clicked:

 So, what happens if one of the XPlan buttons is clicked?  We could just write the execution plan to a text file, but where is the fun in doing that?  How about popping up another web browser page that lists all execution plans for a query that are currently in the library cache, the reasons for those generated execution plans from V$SQL_SHARED_CURSOR, and the bind variable definitions from V$SQL_BIND_METADATA.  The generated web page might look something like this (with duplicate sections from the different child cursors removed to save space):

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
LOAD_OPTIMIZER_STATS
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 1
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
WORK_ORDER WO,    REQUIREMENT R,    PART P  WHERE  
  WO.TYPE='W'    AND WO.SUB_ID='0'    AND WO.STATUS IN ('F','R','U')    
AND WO.DESIRED_QTY>WO.RECEIVED_QTY    AND WO.PART_ID= :1    AND 
R.WORKORDER_TYPE='W'    AND WO.TYPE=R.WORKORDER_TYPE    AND 
WO.BASE_ID=R.WORKORDER_BASE_ID    AND WO.LOT_ID=R.WORKORDER_LOT_ID    
AND WO.SPLIT_ID=R.WORKORDER_SPLIT_ID    AND R.SUBORD_WO_SUB_ID IS NULL  
  AND R.CALC_QTY>R.ISSUED_QTY    AND R.PART_ID=P.ID  ORDER BY    
R.PART_ID

Plan hash value: 3990487722

------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name            | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                 |       |       |    27 (100)|          |        |
|   1 |  SORT UNIQUE                    |                 |     9 |   747 |    26   (4)| 00:00:01 |        |
|   2 |   NESTED LOOPS                  |                 |       |       |            |          |        |
|   3 |    NESTED LOOPS                 |                 |     9 |   747 |    25   (0)| 00:00:01 |        |
|   4 |     NESTED LOOPS                |                 |     9 |   621 |    16   (0)| 00:00:01 |        |
|*  5 |      TABLE ACCESS BY INDEX ROWID| WORK_ORDER      |     1 |    37 |    13   (0)| 00:00:01 |   OR11 |
|*  6 |       INDEX RANGE SCAN          | X_WORK_ORDER_1  |    21 |       |     3   (0)| 00:00:01 |   OR11 |
|*  7 |      TABLE ACCESS BY INDEX ROWID| REQUIREMENT     |    25 |   800 |     3   (0)| 00:00:01 |   OR11 |
|*  8 |       INDEX RANGE SCAN          | X_REQUIREMENT_5 |     1 |       |     2   (0)| 00:00:01 |   OR11 |
|*  9 |     INDEX UNIQUE SCAN           | SYS_C0011459    |     1 |       |     0   (0)|          |   OR11 |
|  10 |    TABLE ACCESS BY INDEX ROWID  | PART            |     1 |    14 |     1   (0)| 00:00:01 |   OR11 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - filter(("WO"."DESIRED_QTY">"WO"."RECEIVED_QTY" AND "WO"."SUB_ID"='0' AND 
              INTERNAL_FUNCTION("WO"."STATUS") AND "WO"."TYPE"='W'))
   6 - access("WO"."PART_ID"=:1)
   7 - filter("R"."CALC_QTY">"R"."ISSUED_QTY")
   8 - access("WO"."TYPE"="R"."WORKORDER_TYPE" AND "WO"."BASE_ID"="R"."WORKORDER_BASE_ID" AND 
              "WO"."LOT_ID"="R"."WORKORDER_LOT_ID" AND "WO"."SPLIT_ID"="R"."WORKORDER_SPLIT_ID" AND 
              "R"."SUBORD_WO_SUB_ID" IS NULL)
       filter("R"."WORKORDER_TYPE"='W')
   9 - access("R"."PART_ID"="P"."ID")

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
ROW_LEVEL_SEC_MISMATCH
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 2
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
...
Plan hash value: 3990487722

------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name            | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                 |       |       |    27 (100)|          |        |
|   1 |  SORT UNIQUE                    |                 |     9 |   747 |    26   (4)| 00:00:01 |        |
|   2 |   NESTED LOOPS                  |                 |       |       |            |          |        |
|   3 |    NESTED LOOPS                 |                 |     9 |   747 |    25   (0)| 00:00:01 |        |
|   4 |     NESTED LOOPS                |                 |     9 |   621 |    16   (0)| 00:00:01 |        |
|*  5 |      TABLE ACCESS BY INDEX ROWID| WORK_ORDER      |     1 |    37 |    13   (0)| 00:00:01 |   OR11 |
|*  6 |       INDEX RANGE SCAN          | X_WORK_ORDER_1  |    21 |       |     3   (0)| 00:00:01 |   OR11 |
|*  7 |      TABLE ACCESS BY INDEX ROWID| REQUIREMENT     |    25 |   800 |     3   (0)| 00:00:01 |   OR11 |
|*  8 |       INDEX RANGE SCAN          | X_REQUIREMENT_5 |     1 |       |     2   (0)| 00:00:01 |   OR11 |
|*  9 |     INDEX UNIQUE SCAN           | SYS_C0011459    |     1 |       |     0   (0)|          |   OR11 |
|  10 |    TABLE ACCESS BY INDEX ROWID  | PART            |     1 |    14 |     1   (0)| 00:00:01 |   OR11 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - filter(("WO"."DESIRED_QTY">"WO"."RECEIVED_QTY" AND "WO"."SUB_ID"='0' AND 
              INTERNAL_FUNCTION("WO"."STATUS") AND "WO"."TYPE"='W'))
   6 - access("WO"."PART_ID"=:1)
   7 - filter("R"."CALC_QTY">"R"."ISSUED_QTY")
   8 - access("WO"."TYPE"="R"."WORKORDER_TYPE" AND "WO"."BASE_ID"="R"."WORKORDER_BASE_ID" AND 
              "WO"."LOT_ID"="R"."WORKORDER_LOT_ID" AND "WO"."SPLIT_ID"="R"."WORKORDER_SPLIT_ID" AND 
              "R"."SUBORD_WO_SUB_ID" IS NULL)
       filter("R"."WORKORDER_TYPE"='W')
   9 - access("R"."PART_ID"="P"."ID")

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
ROW_LEVEL_SEC_MISMATCH
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 3
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
...

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
LOAD_OPTIMIZER_STATS
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 4
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
...

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
ROW_LEVEL_SEC_MISMATCH
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 5
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
...
 
**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
ROW_LEVEL_SEC_MISMATCH
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 7
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
...
Plan hash value: 1336181825

------------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name            | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |                 |       |       |   577 (100)|          |        |
|   1 |  SORT UNIQUE                          |                 |   838 | 69554 |   576   (1)| 00:00:07 |        |
|*  2 |   HASH JOIN                           |                 |   838 | 69554 |   575   (1)| 00:00:07 |        |
|   3 |    NESTED LOOPS                       |                 |       |       |            |          |        |
|   4 |     NESTED LOOPS                      |                 |   840 | 57960 |   164   (0)| 00:00:02 |        |
|*  5 |      TABLE ACCESS BY INDEX ROWID      | WORK_ORDER      |    35 |  1295 |    60   (0)| 00:00:01 |   OR11 |
|   6 |       BITMAP CONVERSION TO ROWIDS     |                 |       |       |            |          |        |
|   7 |        BITMAP AND                     |                 |       |       |            |          |        |
|   8 |         BITMAP CONVERSION FROM ROWIDS |                 |       |       |            |          |        |
|*  9 |          INDEX RANGE SCAN             | X_WORK_ORDER_1  | 13721 |       |     8   (0)| 00:00:01 |   OR11 |
|  10 |         BITMAP OR                     |                 |       |       |            |          |        |
|  11 |          BITMAP CONVERSION FROM ROWIDS|                 |       |       |            |          |        |
|* 12 |           INDEX RANGE SCAN            | X_WORK_ORDER_2  | 13721 |       |     6   (0)| 00:00:01 |   OR11 |
|  13 |          BITMAP CONVERSION FROM ROWIDS|                 |       |       |            |          |        |
|* 14 |           INDEX RANGE SCAN            | X_WORK_ORDER_2  | 13721 |       |     1   (0)| 00:00:01 |   OR11 |
|  15 |          BITMAP CONVERSION FROM ROWIDS|                 |       |       |            |          |        |
|* 16 |           INDEX RANGE SCAN            | X_WORK_ORDER_2  | 13721 |       |    19   (0)| 00:00:01 |   OR11 |
|* 17 |      INDEX RANGE SCAN                 | X_REQUIREMENT_5 |     1 |       |     2   (0)| 00:00:01 |   OR11 |
|* 18 |     TABLE ACCESS BY INDEX ROWID       | REQUIREMENT     |    24 |   768 |     3   (0)| 00:00:01 |   OR11 |
|  19 |    TABLE ACCESS FULL                  | PART            | 37032 |   506K|   410   (1)| 00:00:05 |   OR11 |
------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("R"."PART_ID"="P"."ID")
   5 - filter(("WO"."DESIRED_QTY">"WO"."RECEIVED_QTY" AND "WO"."SUB_ID"='0' AND "WO"."TYPE"='W'))
   9 - access("WO"."PART_ID"=:1)
  12 - access("WO"."STATUS"='F')
  14 - access("WO"."STATUS"='R')
  16 - access("WO"."STATUS"='U')
  17 - access("WO"."TYPE"="R"."WORKORDER_TYPE" AND "WO"."BASE_ID"="R"."WORKORDER_BASE_ID" AND 
              "WO"."LOT_ID"="R"."WORKORDER_LOT_ID" AND "WO"."SPLIT_ID"="R"."WORKORDER_SPLIT_ID" AND 
              "R"."SUBORD_WO_SUB_ID" IS NULL)
       filter("R"."WORKORDER_TYPE"='W')
  18 - filter("R"."CALC_QTY">"R"."ISSUED_QTY")

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 8
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
SYSADM.WORK_ORDER WO,    SYSADM.REQUIREMENT R,    SYSADM.PART P  WHERE  
  WO.TYPE='W'    AND WO.SUB_ID='0'    AND WO.STATUS IN ('F','R','U')    
AND WO.DESIRED_QTY>WO.RECEIVED_QTY    AND WO.PART_ID= :1    AND 
R.WORKORDER_TYPE='W'    AND WO.TYPE=R.WORKORDER_TYPE    AND 
WO.BASE_ID=R.WORKORDER_BASE_ID    AND WO.LOT_ID=R.WORKORDER_LOT_ID    
AND WO.SPLIT_ID=R.WORKORDER_SPLIT_ID    AND R.SUBORD_WO_SUB_ID IS NULL  
  AND R.CALC_QTY>R.ISSUED_QTY    AND R.PART_ID=P.ID  ORDER BY    
R.PART_ID

Plan hash value: 3990487722

------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name            | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                 |       |       |    27 (100)|          |        |
|   1 |  SORT UNIQUE                    |                 |     9 |   747 |    26   (4)| 00:00:01 |        |
|   2 |   NESTED LOOPS                  |                 |       |       |            |          |        |
|   3 |    NESTED LOOPS                 |                 |     9 |   747 |    25   (0)| 00:00:01 |        |
|   4 |     NESTED LOOPS                |                 |     9 |   621 |    16   (0)| 00:00:01 |        |
|*  5 |      TABLE ACCESS BY INDEX ROWID| WORK_ORDER      |     1 |    37 |    13   (0)| 00:00:01 |   OR11 |
|*  6 |       INDEX RANGE SCAN          | X_WORK_ORDER_1  |    21 |       |     3   (0)| 00:00:01 |   OR11 |
|*  7 |      TABLE ACCESS BY INDEX ROWID| REQUIREMENT     |    24 |   768 |     3   (0)| 00:00:01 |   OR11 |
|*  8 |       INDEX RANGE SCAN          | X_REQUIREMENT_5 |     1 |       |     2   (0)| 00:00:01 |   OR11 |
|*  9 |     INDEX UNIQUE SCAN           | SYS_C0011459    |     1 |       |     0   (0)|          |   OR11 |
|  10 |    TABLE ACCESS BY INDEX ROWID  | PART            |     1 |    14 |     1   (0)| 00:00:01 |   OR11 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - filter(("WO"."DESIRED_QTY">"WO"."RECEIVED_QTY" AND "WO"."SUB_ID"='0' AND 
              INTERNAL_FUNCTION("WO"."STATUS") AND "WO"."TYPE"='W'))
   6 - access("WO"."PART_ID"=:1)
   7 - filter("R"."CALC_QTY">"R"."ISSUED_QTY")
   8 - access("WO"."TYPE"="R"."WORKORDER_TYPE" AND "WO"."BASE_ID"="R"."WORKORDER_BASE_ID" AND 
              "WO"."LOT_ID"="R"."WORKORDER_LOT_ID" AND "WO"."SPLIT_ID"="R"."WORKORDER_SPLIT_ID" AND 
              "R"."SUBORD_WO_SUB_ID" IS NULL)
       filter("R"."WORKORDER_TYPE"='W')
   9 - access("R"."PART_ID"="P"."ID")

**********************************************************************************************
Reason for Child Cursor Creation
BIND_MISMATCH
LOAD_OPTIMIZER_STATS
**********
Bind Variable Definitions
  Position:1  Max Length:32  VARCHAR2  Name:1
**********
SQL_ID  8p3pacrbngv80, child number 9
-------------------------------------
SELECT DISTINCT    R.PART_ID,    P.FABRICATED,    P.PURCHASED  FROM    
...
**********************************************************************************************

In the above, the selected session was actually using the execution plan for child number 3.  Notice that one of the execution plans converted normal B*Tree indexes on the fly to permit comparisons much like what are possible with bitmap indexes.  A large portion of the execution plans were created, at least in part, because of a bind mismatch – see the documentation V$SQL_SHARED_CURSOR for more information.

This example requires at a minimum Oracle Database 10.1.0.1 running on Windows, Unix, or Linux.  The supplied script must be run from a Windows client computer.  You will need to specify a suitable username, password, and database name (from tnsnames.ora) for the strUsername, strPassword, and strDatabase variables in the VBS script.  This script ties into several of the chapters in the Expert Oracle Practices book.

Download the script from here: MonitorDatabaseTimeModel.vbs (save as MonitorDatabaseTimeModel.vbs, without the .doc extension – note that this is version 2.0.1)








Follow

Get every new post delivered to your Inbox.

Join 139 other followers