(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)
Charles Hooper's Oracle Notes 
Fixed a problem in the original script with the delta values of the session level wait events not calculating correctly in the script due to a missing explicit data type conversion function. Added in the 2.0.1 version the last update date/time, CPU utilization percent, and User Mode CPU utilization percent.
Big improvement to already very hand first version in a short time Charles.
It is amazing/inspiring to see how you can cope with
Managing a team (from my understanding you are a permanent employee)
Answering questions on forums
Writing min 5 posts a week (your frequency is currently biggest problems against my blogroll report 🙂 I cannot keep up )
Developing the tools and sharing them
Writing book
preparing for presentations and giving them
and god knows what is going on in Oak table mailing list 🙂
Thank you very much for this script and your contributions Charles. you are definitely the most fruitful blogger since you started
Coskan,
Thanks for stopping by and offering a compliment to me regarding the blog. I was concerned that when I started the blog on November 30, 2009 that I would have little or nothing that is useful to offer to visitors of the blog. In the 97 days that have elapsed since the start of the blog, there are 154 published blog articles with 2 more that are just about ready to appear on Monday and Tuesday – that means I have averaged 1.6 blog articles per day. But I have been slowing down lately, as you mention, to just 5 blog articles per week because I am running out of what I consider to be interesting topics. There are so many great Oracle blogs on the Internet, and that makes it difficult to find topics that have not already been written much better than any blog article that I could put together (the blogs of Jonathan Lewis and Richard Foote immediately come to mind).
Yes, I have been a permanent employee for the last 10 years at my current employer. DBA work is just one component (seemingly small in the big picture) of my responsibilities at the company. The days are typically quite long, but I try to set aside time each day to learn something new, or try to remember something that I once knew and have since forgotten. Participating in the forums helps quite a bit to keep me from forgetting too much, as does maintaining this blog. Writing the two chapters for the book with Randolf also helped a lot to keep from forgetting things and to learn new things – Randolf caught a lot of silly mistakes and faulty reasoning in the chapters before I had a chance to analyze the technical details of the chapters. Without Randolf’s contributions in the chapters (some days he worked as late as 2 AM on the chapters), the technical quality of the chapters would not have met, much less exceeded, my expectations.
There are some very technical discussions on the OakTable mailing list. When I was offered membership in 2008 my name was added to a list with 61 other people’s names – I suspected that all 61 of the other people knew more about Oracle’s inner workings than I did. Nearly two years later my name is still on the list, now with about 80 other names – now I am certain that all 80+ of the other people on the list know more about Oracle’s inner workings than I do, but at least that recognition serves as an incentive to continue learning, and hopefully reduce the rate at which I forget things.
Woow long answer for a busy man again. About the book I have one more chapter left and your two chapter is in my top 5 list. I have been following you and Randolf since the beginning and what I can easily say is those two chapters have nearly same type of authoring like your blogs and I while reading I was wondering what was Randolfs part but now I know that Randolf was working behind the scenes. I really enjoyed reading and thank you both for writing them. I hope I will finish my review and be the first non-author review of the book 😉
For the above script I could not find anything about disabling the trace in the code, I wonder if forgot to put it or did not put it on purpose. If it is on purpose I would really appreciate, if you can share the idea behind it
By the way I have changed the code to get the hardcoded values as parameters for ease of use.
I call the script like
script.vbs USERNAME PWD TNSNAME ITERATION INTERVAL
The link is below
http://docs.google.com/Doc?docid=0ARz3zF3bexacZGd6NnpuZm5fMjJkaDU4eDdkeA&hl=en
Thanks for stopping by.
Just to clarify (my initial response may have been misleading), I did not write all of the contents of the two chapters, and Randolf did not just act behind the scenes. Randolf’s knowledge of 10053 trace files (yes he wrote that section), parallel queries, partitioning, and for many other subtopics exceeds my knowledge of those subtopics. Randolf worked behind the scenes on the portions of the chapters that I wrote, and I did the same for the sections of the chapters that he wrote. I had a couple of weeks (maybe a month) of a head start on the writing compared to Randolf because of the demands placed on his time by his employer, so he had the fun of reading through about 40-70 pages of material before I had a chance to even start proofreading. Once all of the sections were written, I went through the chapters with Randolf’s assistance to standardize the writing style, and make certain that the chapters were written using formal English, rather than the casual English style writing that you see in our blogs.
I am very happy that our chapters are in your top 5 list. I am looking forward to your review of the book.
You are correct that I did not provide a method to disable the 10046 trace in the script – that was intentional. The great thing about the scripts that I have provided is that if you follow the pattern and logic of the scripts, you can easily extend the scripts for other tasks, such as adding another button to disable the 10046 trace, removing the hardcoded username and password, etc. Someone else took my automated DBMS_XPLAN tool and added a logon window to remove the hardcoded username and password.
I think I was misunderstood too. I did not intend to say that Randolf was behind the scenes but after reading chapters and knowing both your writing style, my initial thought was that this writing style mostly looks like Charles Hoopers style and thats why I use that term.
Anyways thank you very much for the clarification for both chapters and script. Now I have a homework to put disable option to sqltrace
[…] the time model statistics and wait events – driven by a VBS script, but can also be driven Excel: https://hoopercharles.wordpress.com/2010/02/09/working-with-oracle%e2%80%99s-time-model-data-3/ Example of building Excel charts on demand using data from Oracle: […]