Having fun with Oracle 11g new feature Real Time SQL Monitoring.
The real-time SQL monitoring is a new feature introduced in Oracle 11g which enables to monitor the performance of SQL statements. RT SQL monitoring is automatically started when “a SQL statement runs parallel or when it has consumed at least 5 seconds of CPU or I/O time” (oracle document).
There are lots of article available on this topics. So over here I won’t be explaining RT, but I will show how much fun I had to identify the query performance with the help of RT SQL Monitoring.
Started with finding out sql query consuming more cpu and buffer.
SQL> set lin 200 SQL> select to_char(key), SID, PROCESS_NAME, SQL_ID, SQL_PLAN_HASH_VALUE, ELAPSED_TIME, CPU_TIME, FETCHES, BUFFER_GETS, DISK_READS, DIRECT_WRITES from v$sql_monitor where sid=5427 order by BUFFER_GETS; TO_CHAR(KEY) SID PROCE SQL_ID SQL_PLAN_HASH_VALUE ELAPSED_TIME CPU_TIME FETCHES BUFFER_GETS DISK_READS DIRECT_WRITES --------------- ----- ----- ------------- ------------------- ------------ ---------- ---------- ----------- ---------- ------------- 4698694221941 5427 p003 dbmt8tuqdmhkr 2586784828 4208 0 0 0 0 0 777389080670 5427 p003 dbmt8tuqdmhkr 2586784828 2505 0 0 0 0 0 3642132267135 5427 p006 3rudan1g7sjw2 42911674 2766 0 0 3 0 0 8143257993294 5427 p007 0r3nf6rvn31z0 1253339728 16415 0 0 3 0 0 4561255268456 5427 p007 0r3nf6rvn31z0 1253339728 1000 0 0 3 0 0 8194797600905 5427 p009 0r3nf6rvn31z0 1253339728 3262 0 0 3 0 0 3135326126226 5427 p007 dbmt8tuqdmhkr 2586784828 3010 0 0 3 0 0 798863917352 5427 ora 1uwwsftbgsd53 1074036103 226929 0 1 6 0 0 4114578669875 5427 ora bjgb860t3y6zd 1074036103 10981 0 1 6 0 0 1026497183907 5427 p006 gk56jj46sduya 2394694105 23067861 340000 0 35653 34664 0 163208757466 5427 p007 1uwwsftbgsd53 1074036103 18590991 320000 0 57196 57087 0 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 20584580 280000 0 57314 57205 0 4604204941534 5427 p005 bjgb860t3y6zd 1074036103 19904074 310000 0 59520 59402 0 1541893259589 5427 p001 bjgb860t3y6zd 1074036103 19720584 280000 0 59884 59766 0 180388626746 5427 p002 1uwwsftbgsd53 1074036103 19459474 330000 0 60630 60503 0 5901285064890 5427 p007 1uwwsftbgsd53 1074036103 26312501 360000 0 61614 61496 0 279172874475 5427 ora 0x7kv92ss0zrk 1440161004 11468996 7250000 0 2247848 0 0 6717328851178 5427 ora 859x2aajaprhx 23783937 13659015 8580000 0 2564259 0 0 1567663063277 5427 ora 3772smcjv0qkj 1440161004 13799946 8750000 0 2671145 0 0 3990024618220 5427 ora d3dg18xr474mp 1440161004 15693815 9910000 0 3027751 0 0 94489280745 5427 ora 57bazpha8f1wn 3727349365 65193558 41390000 0 11383381 1 0 21 rows selected.
Went for sql id 57bazpha8f1wn. Now from v$sql_plan_monitor I can find the query detail plan.
SQL> select to_char(key), SID, PROCESS_NAME, SQL_ID, SQL_PLAN_HASH_VALUE, PLAN_OPERATION, PLAN_OPTIONS, OUTPUT_ROWS, WORKAREA_MEM, WORKAREA_MAX_MEM, WORKAREA_TEMPSEG, WORKAREA_MAX_TEMPSEG from v$sql_plan_monitor where key=94489280745; TO_CHAR(KEY) SID PROCE SQL_ID SQL_PLAN_HASH_VALUE PLAN_OPERATION PLAN_OPTIONS OUTPUT_ROWS WORKAREA_MEM WORKAREA_MAX_MEM WORKAREA_TEMPSEG WORKAREA_MAX_TEMPSEG ------------------- ------ ----- ------------- ------------------- ------------------ ----------------- ----------- ------------ ---------------- ---------------- -------------------- 94489280745 5427 ora 57bazpha8f1wn 3727349365 UPDATE STATEMENT 1 94489280745 5427 ora 57bazpha8f1wn 3727349365 UPDATE 1 94489280745 5427 ora 57bazpha8f1wn 3727349365 TABLE ACCESS BY INDEX ROWID 1 94489280745 5427 ora 57bazpha8f1wn 3727349365 INDEX UNIQUE SCAN 1
With dbms_sqltune.report_sql_monitor, I was quite impressed with the detail output like what is the sql read count, buffer gets, IO wait ,CPU time and so on with details on query plan as well.
SQL> set lin 200
SQL> set long 10000000
SQL> set longchunksize 10000000
SQL> select dbms_sqltune.report_sql_monitor('57bazpha8f1wn',5427) from dual;
DBMS_SQLTUNE.REPORT_SQL_MONITOR('57BAZPHA8F1WN',5427)
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
SQL Text
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
UPDATE Accounts_Retail SET Accounts_Retail.OrgKey = :1 , Accounts_Retail.OrgName = :2, Accounts_Retail.Add1_First_Name = :3, Accounts_Retail.Add1_Last_Name = :4,
Accounts_Retail.Add1_Middle_Name = :5, Accounts_Retail.Add2_First_Name = :6, Accounts_Retail.Add2_Last_Name = :7, Accounts_Retail.Add2_Middle_Name = :8,
Accounts_Retail.Add3_First_Name = :9, Accounts_Retail.Add3_Last_Name = :10, Accounts_Retail.Add3_Middle_Name = :11, Accounts_Retail.Add4_First_Name = :12,
Accounts_Retail.Add4_Last_Name = :13, Accounts_Retail.Add4_Middle_Name = :14, Accounts_Retail.Add5_First_Name = :15, Accounts_Retail.Add5_Last_Name = :16,
Accounts_Retail.Add5_Middle_Name = :17, Accounts_Retail.Alert1 = :18, Accounts_Retail.Alert2 = :19, Accounts_Retail.Alert3 = :20, Accounts_Retail.AlreadyCreatedInEBanking = :21,
Accounts_Retail.Amount1 = :22, Accounts_Retail.Amount10 = :23, Accounts_Retail.Amount11 = :24, Accounts_Retail.Amount12 = :25, Accounts_Retail.Amount2 = :26,
Accounts_Retail.Amount3 = :27, Accounts_Retail.Amount4 = :28, Accounts_Retail.Amount5 = :29, Accounts_Retail.Amount6 = :30, Accounts_Retail.Amount7 = :31, Accounts_Retail.Amount8
= :32, Accounts_Retail.Amount9 = :33, Accounts_Retail.AssignedByUserID = :34, Accounts_Retail.AssignedLocationID = :35, Accounts_Retail.AssignedTo = :36,
Accounts_Retail.AssignedToGroup = :37, Accounts_Retail.Assistant = :38, Accounts_Retail.AutoApproval = :39, Accounts_Retail.BackEndID = :40, Accounts_Retail.Birth_Day = :41,
Accounts_Retail.Birth_Month = :42, Accounts_Retail.Birth_Year = :43, Accounts_Retail.BlackListed = :44, Accounts_Retail.Blacklist_Notes = :45, Accounts_Retail.Blacklist_Reason =
:46, Accounts_Retail.CIN = :47, Accounts_Retail.Category = :48, Accounts_Retail.ChargeLevelCode = :49, Accounts_Retail.CheckSum = :50, Accounts_Retail.City = :51,
Accounts_Retail.CombinedStatementFlg = :52, Accounts_Retail.Constitution_Code = :53, Accounts_Retail.Constitution_ref_code = :54, Accounts_Retail.Core_cust_id = :55,
Accounts_Retail.Core_introd_cust_id = :56, Accounts_Retail.CorpRepCount = :57, Accounts_Retail.CountryOfBirth = :58, Accounts_Retail.CreatedBySystemID = :59,
Accounts_Retail.CreatedLocationID = :60, Accounts_Retail.Created_From = :61, Accounts_Retail.CreditBureauDescription = :62, Accounts_Retail.CreditBureauRequestDate = :63,
Accounts_Retail.CreditBureauScore = :64, Accounts_Retail.CreditBureauScoreValidity = :65, Accounts_Retail.Crncy_code = :66, Accounts_Retail.CurrNumNegEsc = :67,
Accounts_Retail.CurrNumPosEsc = :68, Accounts_Retail.CurrStepDueDate = :69, Accounts_Retail.CurrentStep = :70, Accounts_Retail.custclass = :71, Accounts_Retail.CustCreationMode =
:72, Accounts_Retail.CustStatusChgDate = :73, Accounts_Retail.Cust_DOB = :74, Accounts_Retail.Cust_First_Name = :75, Accounts_Retail.Cust_First_Name_Native = :76,
Accounts_Retail.Cust_First_Name_Native1 = :77, Accounts_Retail.Cust_First_Name_alt1 = :78, Accounts_Retail.Cust_Language = :79, Accounts_Retail.Cust_Last_Name = :80,
Accounts_Retail.Cust_Last_Name_Native = :81, Accounts_Retail.Cust_Last_Name_Native1 = :82, Accounts_Retail.Cust_Last_Name_alt1 = :83, Accounts_Retail.Cust_Middle_Name = :84,
Accounts_Retail.Cust_Middle_Name_Native = :85, Accounts_Retail.Cust_Middle_Name_Native1 = :86, Accounts_Retail.Cust_Middle_Name_alt1 = :87, Accounts_Retail.Cust_Staff_Status =
:88, Accounts_Retail.Cust_Swift_Code_Desc = :89, Accounts_Retail.Cust_Type = :90, Accounts_Retail.Cust_commu_code = :91, Accounts_Retail.Cust_community = :92,
Accounts_Retail.Cust_hlth = :93, Accounts_Retail.Cust_hlth_code = :94, Accounts_Retail.Cust_pref_till_date = :95, Accounts_Retail.Cust_type_code = :96,
Accounts_Retail.CustomerMinor = :97, Accounts_Retail.CustomerNREFlg = :98, Accounts_Retail.CustomerRelationshipNo = :99, Accounts_Retail.CustomerTrade = :100,
Accounts_Retail.Customer_Level_Provisioning = :101, Accounts_Retail.DSA_ID = :102, Accounts_Retail.DateOfBe
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Global Information
Status : DONE
Instance ID : 1
DBMS_SQLTUNE.REPORT_SQL_MONITOR('57BAZPHA8F1WN',5427)
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Session ID : 5427
SQL ID : 57bazpha8f1wn
SQL Execution ID : 16777218
Plan Hash Value : 3727349365
Execution Started : 08/08/2011 15:46:51
First Refresh Time : 08/08/2011 15:47:01
Last Refresh Time : 08/08/2011 15:47:57
----------------------------------------------------------------------
| Elapsed | Cpu | IO | PL/SQL | Other | Buffer | Reads |
| Time(s) | Time(s) | Waits(s) | Time(s) | Waits(s) | Gets | |
----------------------------------------------------------------------
| 65 | 41 | 0.01 | 0.00 | 24 | 11383K | 1 |
----------------------------------------------------------------------
SQL Plan Monitoring Details
==========================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (percent) | (sample #) |
==========================================================================================================================================
| 0 | UPDATE STATEMENT | | | 1 | 57 | +10 | 1 | 1 | | |
| 1 | UPDATE | ACCOUNTS | | | 57 | +10 | 1 | 1 | | |
| 2 | TABLE ACCESS BY INDEX ROWID | ACCOUNTS | 1 | 1 | 1 | +10 | 1 | 1 | | |
| 3 | INDEX UNIQUE SCAN | PK1 | 1 | 1 | 57 | +10 | 1 | 1 | | |
==========================================================================================================================================
SQL>
Great report, so why not get details for parallel queries.
Looked for sql id bjgb860t3y6zd. Plan with parallel execution.
SQL> select to_char(key), SID, PROCESS_NAME, SQL_ID, SQL_PLAN_HASH_VALUE, PLAN_OPERATION, PLAN_OPTIONS, OUTPUT_ROWS, WORKAREA_MEM, WORKAREA_MAX_MEM, WORKAREA_TEMPSEG, WORKAREA_MAX_TEMPSEG from v$sql_plan_monitor where key=5261334937798; TO_CHAR(KEY) SID PROCE SQL_ID SQL_PLAN_HASH_VALUE PLAN_OPERATION PLAN_OPTIONS OUTPUT_ROWS WORKAREA_MEM WORKAREA_MAX_MEM WORKAREA_TEMPSEG WORKAREA_MAX_TEMPSEG --------------- ------ ----- ------------- ------------------- ----------------- ------------- ----------- ------------ ---------------- ---------------- -------------------- 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 SELECT STATEMENT 0 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 SORT AGGREGATE 0 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 PX COORDINATOR 0 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 PX SEND QC (RANDOM) 1 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 SORT AGGREGATE 1 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 PX BLOCK ITERATOR 0 5261334937798 5427 p006 bjgb860t3y6zd 1074036103 TABLE ACCESS FULL 0 7 rows selected.
Lets check details with dbms_sqltune.report_sql_monitor.
SQL> select dbms_sqltune.report_sql_monitor from dual; REPORT_SQL_MONITOR -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- SQL Monitoring Report SQL Text ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Select /*+PARALLEL(Accounts 20)*/ count(0) from Accounts where corp_Id is not null AND BANK_ID = :1 ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Global Information Status : DONE (ALL ROWS) Instance ID : 1 Session ID : 5454 REPORT_SQL_MONITOR -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- SQL ID : bjgb860t3y6zd SQL Execution ID : 16777222 Plan Hash Value : 1074036103 Execution Started : 08/08/2011 19:10:39 First Refresh Time : 08/08/2011 19:10:39 Last Refresh Time : 08/08/2011 19:11:00 -------------------------------------------------------------------- | Elapsed | Cpu | IO | Other | Fetch | Buffer | Reads | | Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | | -------------------------------------------------------------------- | 199 | 2.85 | 195 | 1.18 | 1 | 594K | 592K | -------------------------------------------------------------------- Parallel Execution Details (DOP=10) ============================================================================================================= | Name | Type | Server# | Elapsed | Cpu | IO | Other | Buffer | Reads | Wait Events | | | | | Time(s) | Time(s) | Waits(s) | Waits(s) | Gets | | (sample #) | ============================================================================================================= | PX Coordinator | QC | | 0.01 | | | 0.01 | 6 | | | | p000 | Set 1 | 1 | 20 | 0.29 | 20 | 0.11 | 59984 | 59866 | | | p001 | Set 1 | 2 | 19 | 0.30 | 19 | 0.12 | 58507 | 58389 | | | p002 | Set 1 | 3 | 20 | 0.29 | 20 | 0.12 | 59849 | 59731 | | | p003 | Set 1 | 4 | 20 | 0.29 | 20 | 0.13 | 60359 | 60241 | | | p004 | Set 1 | 5 | 20 | 0.26 | 20 | 0.10 | 59526 | 59408 | | | p005 | Set 1 | 6 | 20 | 0.27 | 20 | 0.11 | 59620 | 59502 | | | p006 | Set 1 | 7 | 19 | 0.26 | 19 | 0.12 | 57435 | 57326 | | | p007 | Set 1 | 8 | 20 | 0.30 | 20 | 0.11 | 58228 | 58101 | | | p008 | Set 1 | 9 | 20 | 0.30 | 20 | 0.12 | 60476 | 60358 | | | p009 | Set 1 | 10 | 20 | 0.29 | 19 | 0.12 | 59527 | 59409 | | ============================================================================================================= REPORT_SQL_MONITOR -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- SQL Plan Monitoring Details ==================================================================================================================================== | Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail | | | | | (Estim) | | Active(s) | Active | | (Actual) | (percent) | (sample #) | ==================================================================================================================================== | 0 | SELECT STATEMENT | | | 8936 | 1 | +21 | 1 | 1 | | | | 1 | SORT AGGREGATE | | 1 | | 1 | +21 | 1 | 1 | | | | 2 | PX COORDINATOR | | | | 1 | +21 | 11 | 10 | | | | 3 | PX SEND QC (RANDOM) | :TQ10000 | 1 | | 3 | +19 | 10 | 10 | | | | 4 | SORT AGGREGATE | | 1 | | 4 | +18 | 10 | 10 | | | | 5 | PX BLOCK ITERATOR | | 299K | 8936 | 4 | +18 | 10 | 305K | | | | 6 | TABLE ACCESS FULL | ACCOUNTS | 299K | 8936 | 20 | +2 | 130 | 305K | | | ====================================================================================================================================
Getting those IO, CPU details with plan statistics also output showing on Parallel Execution Details. What else, if we wonna tune the query if required we can have an help from sql advisor.
SQL> SET SERVEROUTPUT ON
SQL> DECLARE
2 l_sql_tune_task_id VARCHAR2(100);
3 BEGIN
4 l_sql_tune_task_id := DBMS_SQLTUNE.create_tuning_task (
5 sql_id => 'bjgb860t3y6zd',
6 scope => DBMS_SQLTUNE.scope_comprehensive,
7 task_name => 'bjgb860t3y6zd_tuning_task',
8 description => 'Tuning task for statement bjgb860t3y6zd.');
9 DBMS_OUTPUT.put_line('l_sql_tune_task_id: ' || l_sql_tune_task_id);
10 END;
11 /
l_sql_tune_task_id: bjgb860t3y6zd_tuning_task
PL/SQL procedure successfully completed.
SQL> EXEC DBMS_SQLTUNE.execute_tuning_task(task_name => 'bjgb860t3y6zd_tuning_task');
PL/SQL procedure successfully completed.
SQL> SET LONG 10000;
SET PAGESIZE 1000
SET LINESIZE 200
SELECT DBMS_SQLTUNE.report_tuning_task('bjgb860t3y6zd_tuning_task') AS recommendations FROM dual;
SET PAGESIZE 24
SQL> SQL> SQL>
RECOMMENDATIONS
--------------------------------------------------------------------------------
GENERAL INFORMATION SECTION
-------------------------------------------------------------------------------
Tuning Task Name : bjgb860t3y6zd_tuning_task
Tuning Task Owner : SYS
Workload Type : Single SQL Statement
Scope : COMPREHENSIVE
Time Limit(seconds): 1800
Completion Status : COMPLETED
Started at : 08/08/2011 19:31:21
Completed at : 08/08/2011 19:31:30
-------------------------------------------------------------------------------
Schema Name: CRMUSER
SQL ID : bjgb860t3y6zd
SQL Text : Select /*+PARALLEL(Accounts 20)*/ count(0) from Accounts where
corp_Id is not null AND BANK_ID = :1
-------------------------------------------------------------------------------
There are no recommendations to improve the statement.
-------------------------------------------------------------------------------
SQL>
No recommendation for this query, but I just wanted to show how simple things are gonna be.
We can have an EM SQL Mointoring output (html) with the following way,
spool the file as .html
SQL> set long 10000000 SQL> set longchunksize 10000000 SQL> set linesize 200 select dbms_sqltune.report_sql_monitor(type=>'EM', sql_id=>'<>') from dual;
Enabling and Disabling SQL Monitoring – We can also make use of /*+ MONITOR */ or /*+ NO_MONITOR */ hint to have the statistics available or not in both the monitoring views. The real-time SQL monitoring is effective only when the CONTROL_MANAGEMENT_PACK_ACCESS parameter is set to DIAGNOSTIC+TUNING (default).
Below a graphical look that can be viewed in EM Console.
Having detail info, just mouseover to get the detail waits considering IO, CPU, …
Getting idea at database level for all queries.
Ref:
Nicely portrayed in graphical manner by Greg Rahn, Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR
Real-Time SQL Monitoring in 11g [ID 1229904.1]
http://www.pythian.com/news/582/tuning-pack-11g-real-time-sql-monitoring/
http://structureddata.org/2008/01/06/oracle-11g-real-time-sql-monitoring-using-dbms_sqltunereport_sql_monitor/
http://www.oracle.com/technetwork/database/focus-areas/manageability/sqlmonitor-084401.html
Real Time SQL Monitoring, A Goodie Of 11g….
http://www.oracle-base.com/articles/11g/RealTimeSqlMonitoring_11gR1.php
Oracle Documentation
Real-Time SQL Monitoring
V$SQL_MONITOR
V$SQL_PLAN_MONITOR
REPORT_SQL_MONITOR Function
