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

About these ads