Realtime SQL Monitoring – Designed with Exadata in Mind

One of the best new features of 11g from a diagnostic standpoint is the Real Time SQL Monitoring capabilities. I did a post about it a couple of years ago here: Oracle 11g Real Time SQL Monitoring In that post I talked about a procedure (DBMS_SQLTUNE.REPORT_SQL_MONITOR) that provides a very nicely formatted explain plan type output which contains quite a bit of useful information. Well, it has recently come to my attention that the report contains a column that shows cell offloading. That’s pretty cool. Here’s a script to call that procedure, report_sql_monitor.sql, and an example (note the format is really wide so be sure and use the scroll bar at the bottom to see the columns on the right of the output):

SYS@SANDBOX1> @report_sql_monitor.sql
Enter value for sid: 
Enter value for sql_id: 2hzzka3071hkj
Enter value for sql_exec_id: 
 
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
select /*+ INDEX (SKEW2 SKEW2_COL1) */ avg(pk_col) from kso.skew2
 
Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  SYS (3:2673)
 SQL ID              :  2hzzka3071hkj
 SQL Execution ID    :  16777216
 Execution Started   :  03/13/2011 17:02:35
 First Refresh Time  :  03/13/2011 17:02:35
 Last Refresh Time   :  03/13/2011 17:02:48
 Duration            :  13s
 Module/Action       :  sqlplus@Kerry-Osbornes-MacBook-Pro-4.local (TNS /-
 Service             :  SANDBOX
 Program             :  sqlplus@Kerry-Osbornes-MacBook-Pro-4.local (TNS
 Fetch Calls         :  1
 
Global Stats
============================================================================================================================
| Elapsed |   Cpu   |    IO    | Application | Concurrency | Cluster  |  Other   | Fetch | Buffer | Read | Read  |  Cell   |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Offload |
============================================================================================================================
|      96 |      92 |     2.33 |        0.00 |        0.80 |     0.00 |     0.47 |     1 |   653K | 6136 |   5GB |  71.83% |
============================================================================================================================
 
Parallel Execution Details (DOP=8 , Servers Allocated=8)
===================================================================================================================================================================================
|      Name      | Type  | Server# | Elapsed |   Cpu   |    IO    | Application | Concurrency | Cluster  |  Other   | Buffer | Read | Read  |  Cell   |        Wait Events        |
|                |       |         | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Waits(s) |  Gets  | Reqs | Bytes | Offload |        (sample #)         |
===================================================================================================================================================================================
| PX Coordinator | QC    |         |    0.83 |    0.03 |     0.00 |        0.00 |        0.80 |     0.00 |          |      7 |    3 | 24576 |    NaN% |                           |
| p000           | Set 1 |       1 |      12 |      11 |     0.29 |             |             |          |     0.07 |  81601 |  770 | 637MB |  71.83% | cell smart table scan (1) |
| p001           | Set 1 |       2 |      12 |      11 |     0.31 |             |             |          |     0.06 |  81601 |  775 | 637MB |  71.83% |                           |
| p002           | Set 1 |       3 |      12 |      12 |     0.32 |             |        0.00 |          |     0.06 |  81601 |  764 | 637MB |  71.83% | cell smart table scan (1) |
| p003           | Set 1 |       4 |      12 |      11 |     0.25 |             |             |          |     0.04 |  81601 |  768 | 637MB |  71.83% |                           |
| p004           | Set 1 |       5 |      12 |      12 |     0.30 |             |             |          |     0.06 |  81601 |  757 | 637MB |  71.83% | cell smart table scan (1) |
| p005           | Set 1 |       6 |      12 |      11 |     0.26 |             |             |          |     0.05 |  81601 |  755 | 637MB |  71.83% |                           |
| p006           | Set 1 |       7 |      12 |      12 |     0.28 |             |             |          |     0.07 |  81601 |  769 | 637MB |  71.83% |                           |
| p007           | Set 1 |       8 |      12 |      12 |     0.33 |             |             |          |     0.06 |  81560 |  775 | 637MB |  71.83% |                           |
===================================================================================================================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=2117817910)
==============================================================================================================================================================================
| Id |            Operation             |   Name   |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  |  Cell   | Activity |      Activity Detail      |
|    |                                  |          | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Offload |   (%)    |        (# samples)        |
==============================================================================================================================================================================
|  0 | SELECT STATEMENT                 |          |         |       |         1 |    +13 |     1 |        1 |      |       |         |          |                           |
|  1 |   SORT AGGREGATE                 |          |       1 |       |         1 |    +13 |     1 |        1 |      |       |         |          |                           |
|  2 |    PX COORDINATOR                |          |         |       |         1 |    +13 |     9 |        8 |      |       |         |          |                           |
|  3 |     PX SEND QC (RANDOM)          | :TQ10000 |       1 |       |         2 |    +12 |     8 |        8 |      |       |         |          |                           |
|  4 |      SORT AGGREGATE              |          |       1 |       |        13 |     +1 |     8 |        8 |      |       |         |    50.52 | Cpu (49)                  |
|  5 |       PX BLOCK ITERATOR          |          |    128M | 24700 |        13 |     +1 |     8 |     128M |      |       |         |    45.36 | Cpu (44)                  |
|  6 |        TABLE ACCESS STORAGE FULL | SKEW2    |    128M | 24700 |        13 |     +1 |   104 |     128M | 6133 |   5GB |  71.83% |     3.09 | cell smart table scan (3) |
==============================================================================================================================================================================

So as you can see, this is a parallel query. For parallel queries there is a separate section that shows what each slave process did. There are a couple of columns that are particularly interesting in this section. The Cell Offload column shows the percentage reduction in data transferred to the database tier that resulted from offloading. The Wait Events column shows what the slaves waited on. In the Plan Details section you can see that the plan included a full table scan and that it was offloaded. This section has columns that show the same basic information (although the column names are slightly different), but it’s organized by plan step. This is extremely useful on complex statements that have multiple steps which may be offloaded. This section also clearly shows which steps are taking the most time (Activity %).

Here’s a more complicated example. The statement in this example doesn’t have a lot of steps, but the output is very useful in understanding what is happening. Again, be sure to scroll over to the right to see the interesting bits.

SYS@SANDBOX1> @report_sql_monitor
Enter value for sid: 
Enter value for sql_id: fm7y4nqu4tbv3
Enter value for sql_exec_id: 
 
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
update kso.skew_hcc1 set col1 =col1*1
 
Global Information
------------------------------
 Status              :  DONE
 Instance ID         :  1
 Session             :  SYS (451:1843)
 SQL ID              :  fm7y4nqu4tbv3
 SQL Execution ID    :  16777216
 Execution Started   :  04/10/2011 17:41:24
 First Refresh Time  :  04/10/2011 17:41:24
 Last Refresh Time   :  04/10/2011 18:07:16
 Duration            :  1552s
 Module/Action       :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)/-
 Service             :  SYS$USERS
 Program             :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)
 
Global Stats
=========================================================================================================================================
| Elapsed | Queuing |   Cpu   |    IO    | Application | Concurrency | Cluster  | PL/SQL  |  Other   | Buffer | Read  | Read  |  Cell   |
| Time(s) | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Time(s) | Waits(s) |  Gets  | Reqs  | Bytes | Offload |
=========================================================================================================================================
|    1583 |    0.00 |    1442 |      132 |        0.00 |        0.03 |     2.35 |    0.00 |     7.01 |   231M | 63553 | 784MB | -29.87% |
=========================================================================================================================================
 
Parallel Execution Details (DOP=32 , Servers Allocated=32)
====================================================================================================================================================================================================================
|      Name      | Type  | Server# | Elapsed | Queuing |   Cpu   |    IO    | Application | Concurrency | Cluster  | PL/SQL  |  Other   | Buffer | Read  | Read  |  Cell   |              Wait Events              |
|                |       |         | Time(s) | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Time(s) | Waits(s) |  Gets  | Reqs  | Bytes | Offload |              (sample #)               |
====================================================================================================================================================================================================================
| PX Coordinator | QC    |         |    1551 |    0.00 |    1425 |      117 |        0.00 |        0.03 |     2.23 |    0.00 |     6.69 |   231M | 58878 | 460MB |    NaN% | gc current grant 2-way (1)            |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | log buffer space (5)                  |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | log file switch completion (3)        |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | enq: FB - contention (2)              |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | cell single block physical read (122) |
| p000           | Set 1 |       1 |    0.93 |         |    0.53 |     0.39 |             |             |     0.00 |         |          |   1682 |   120 |  10MB | -72.41% | cell smart table scan (2)             |
| p001           | Set 1 |       2 |    0.98 |         |    0.51 |     0.48 |             |             |          |         |          |   1389 |   107 |  10MB | -72.41% | cell single block physical read (1)   |
| p002           | Set 1 |       3 |    0.97 |         |    0.57 |     0.41 |             |             |     0.00 |         |          |   2954 |   181 |  10MB | -66.67% |                                       |
| p003           | Set 1 |       4 |    0.91 |         |    0.51 |     0.40 |             |             |     0.00 |         |          |   1412 |   119 |  10MB | -72.41% |                                       |
| p004           | Set 1 |       5 |    0.92 |         |    0.52 |     0.40 |             |             |     0.00 |         |          |   1415 |   121 |  10MB | -69.49% | cell single block physical read (1)   |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | cell smart table scan (1)             |
| p005           | Set 1 |       6 |    1.31 |         |    0.54 |     0.77 |             |             |     0.00 |         |          |   7985 |   389 |  12MB | -58.73% | cell single block physical read (2)   |
| p006           | Set 1 |       7 |    0.98 |         |    0.48 |     0.50 |             |             |     0.00 |         |          |   2653 |   123 |  10MB | -72.41% |                                       |
| p007           | Set 1 |       8 |    0.96 |         |    0.49 |     0.46 |             |             |     0.00 |         |          |   2926 |   175 |  10MB | -69.49% |                                       |
| p008           | Set 1 |       9 |    0.84 |         |    0.53 |     0.30 |             |             |     0.00 |         |          |   1380 |    98 |  10MB | -75.44% | cell smart table scan (1)             |
| p009           | Set 1 |      10 |    0.81 |         |    0.48 |     0.33 |             |             |     0.00 |         |          |   1389 |   108 |  10MB | -72.41% |                                       |
| p010           | Set 1 |      11 |    1.32 |         |    0.54 |     0.46 |             |             |     0.00 |         |     0.32 |   2283 |    90 |  10MB | -75.44% | cell smart table scan (1)             |
| p011           | Set 1 |      12 |    1.13 |         |    0.44 |     0.68 |             |             |     0.00 |         |          |   1382 |    92 |  10MB | -75.44% | cell smart table scan (1)             |
| p012           | Set 1 |      13 |    1.12 |         |    0.58 |     0.54 |             |             |     0.00 |         |          |   5818 |   238 |  11MB | -66.67% |                                       |
| p013           | Set 1 |      14 |    0.92 |         |    0.55 |     0.37 |             |             |     0.00 |         |          |   1408 |   114 |  10MB | -72.41% |                                       |
| p014           | Set 1 |      15 |    1.12 |         |    0.53 |     0.59 |             |             |     0.00 |         |          |   3604 |   217 |  11MB | -66.67% |                                       |
| p015           | Set 1 |      16 |    0.98 |         |    0.53 |     0.45 |             |             |     0.00 |         |          |   1973 |   110 |  10MB | -75.44% |                                       |
| p016           | Set 1 |      17 |    0.97 |         |    0.51 |     0.46 |             |             |     0.00 |         |          |   1407 |   106 |  10MB | -72.41% | cell single block physical read (2)   |
| p017           | Set 1 |      18 |    0.95 |         |    0.50 |     0.45 |             |             |     0.00 |         |          |   5017 |   210 |  11MB | -69.49% |                                       |
| p018           | Set 1 |      19 |    1.08 |         |    0.52 |     0.56 |             |        0.00 |     0.00 |         |          |   2305 |   156 |  10MB | -69.49% |                                       |
| p019           | Set 1 |      20 |    0.92 |         |    0.49 |     0.42 |             |             |          |         |          |   1366 |    87 |  10MB | -75.44% |                                       |
| p020           | Set 1 |      21 |    0.89 |         |    0.55 |     0.33 |             |             |     0.00 |         |          |   2804 |   107 |  10MB | -72.41% |                                       |
| p021           | Set 1 |      22 |    0.89 |         |    0.53 |     0.35 |             |             |     0.00 |         |          |   1392 |   110 |  10MB | -72.41% | cell smart table scan (1)             |
| p022           | Set 1 |      23 |    0.94 |         |    0.53 |     0.40 |             |             |     0.00 |         |          |   1384 |    97 |  10MB | -72.41% |                                       |
| p023           | Set 1 |      24 |    0.93 |         |    0.52 |     0.41 |             |             |     0.00 |         |          |   9753 |   177 |  10MB | -66.67% |                                       |
| p024           | Set 1 |      25 |    1.07 |         |    0.53 |     0.53 |             |             |     0.00 |         |          |   7194 |   275 |  11MB | -66.67% |                                       |
| p025           | Set 1 |      26 |    1.15 |         |    0.54 |     0.53 |             |             |     0.08 |         |          |   2394 |    96 |  10MB | -75.44% |                                       |
| p026           | Set 1 |      27 |    1.13 |         |    0.54 |     0.59 |             |             |     0.00 |         |          |   5178 |   224 |  11MB | -63.93% | cell smart table scan (1)             |
| p027           | Set 1 |      28 |    0.94 |         |    0.48 |     0.45 |             |             |     0.00 |         |          |   3969 |   151 |  10MB | -69.49% |                                       |
| p028           | Set 1 |      29 |    0.99 |         |    0.54 |     0.45 |             |             |     0.00 |         |          |   1387 |    97 |  10MB | -75.44% | cell smart table scan (1)             |
| p029           | Set 1 |      30 |    0.80 |         |    0.54 |     0.26 |             |             |     0.00 |         |          |   1375 |    90 |  10MB | -75.44% |                                       |
| p030           | Set 1 |      31 |    1.10 |         |    0.62 |     0.48 |             |             |     0.00 |         |          |   2958 |   184 |  10MB | -69.49% | cell smart table scan (1)             |
| p031           | Set 1 |      32 |    1.03 |         |    0.52 |     0.51 |             |             |     0.00 |         |          |   1389 |   106 |  10MB | -69.49% | cell smart table scan (1)             |
====================================================================================================================================================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=3842559352)
==========================================================================================================================================================================================
| Id |            Operation            |   Name    |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read  | Read  |  Cell   | Activity |            Activity Detail            |
|    |                                 |           | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs  | Bytes | Offload |   (%)    |              (# samples)              |
==========================================================================================================================================================================================
|  0 | UPDATE STATEMENT                |           |         |      |           |        |     1 |          |       |       |         |          |                                       |
|  1 |   UPDATE                        | SKEW_HCC1 |         |      |      1552 |     +1 |     1 |        0 | 58650 | 458MB |         |    94.61 | gc current grant 2-way (1)            |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | log buffer space (5)                  |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | log file switch completion (3)        |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | Cpu (1359)                            |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | enq: FB - contention (2)              |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | cell single block physical read (122) |
|  2 |    PX COORDINATOR               |           |         |      |      1551 |     +2 |    33 |      32M |       |       |         |     3.68 | Cpu (58)                              |
|  3 |     PX SEND QC (RANDOM)         | :TQ10000  |     32M |  375 |      1551 |     +2 |    32 |      32M |       |       |         |     0.38 | Cpu (6)                               |
|  4 |      PX BLOCK ITERATOR          |           |     32M |  375 |      1551 |     +2 |    32 |      32M |       |       |         |          |                                       |
|  5 |       TABLE ACCESS STORAGE FULL | SKEW_HCC1 |     32M |  375 |      1551 |     +2 |   417 |      32M |  4675 | 324MB | -69.49% |     1.33 | Cpu (4)                               |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | cell single block physical read (6)   |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | cell smart table scan (11)            |
==========================================================================================================================================================================================
 
 
1 row selected.

In this example, we have an update statement that took a while, even though it was using Smart Scans. So what gives? When we looked at the output from SQL Monitor it was clear that it wasn’t spending all it’s time looking for the records to update, but rather on the update itself. As you might have guessed from the name of the table, this statement was attempting to update every row in a table that had been compressed using HCC (not something you would normally want to do). This caused a lot of extra work, migrating the rows to OLTP compressed blocks. So that’s what’s going on under the covers. The point of the example is that the report quickly focuses our attention on the area that needs investigation.

By the way, SQL Monitoring is supposed to kick in automatically for long running statements (over 5 seconds by default) and for parallel statements. Occasionally though we would like to see the SQL Monitoring Report on a statement that is not being monitored for some reason. Fortunately, there is a hint (MONITOR) that can be used to force SQL Monitoring. In situations where we don’t have access to the code, like a packaged app for example, we can apply the hint via a SQL Profile. I created a little script called fm.sql to do just that. And no fm doesn’t stand a radio frequency range, and no it doesn’t stand for some kind of magic, and no it’s not the name of a Steely Dan song (well it is, but that’s not why I called it that). It stands for “force monitoring”. Here’s an example:

 
 
*******************
Force Monitoring via a SQL Profile
*******************
 
 
SYS@SANDBOX1> select count(*) from kso.little_skew a;
 
  COUNT(*)
----------
   1100098
 
1 row selected.
 
SYS@SANDBOX1> @fsx
Enter value for sql_text: select count(*) from kso.little_skew a
Enter value for sql_id: 
 
SQL_ID         CHILD  PLAN_HASH  EXECS  AVG_ETIME AVG_PX OFFLOAD IO_SAVED_% SQL_TEXT
------------- ------ ---------- ------ ---------- ------ ------- ---------- ----------------------------------------------------------------------
8xrg1nunxn181      0 3498336203      1        .02      0 No             .00 select count(*) from kso.little_skew a
 
1 row selected.
 
SYS@SANDBOX1> @report_sql_monitor
Enter value for sid: 
Enter value for sql_id: 8xrg1nunxn181
Enter value for sql_exec_id: 
 
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
1 row selected.
 
SYS@SANDBOX1> -- It's a short duration non-PX statement so it wasn't monitored
SYS@SANDBOX1> -- let's force monitoring via a profile (we'll create the profile with fm.sql)
SYS@SANDBOX1> 
SYS@SANDBOX1> @fm
Enter value for sql_id: 8xrg1nunxn181
 
Profile PROFILE_8xrg1nunxn181_MONIOTR created.
 
SYS@SANDBOX1> select count(*) from kso.little_skew a;
 
  COUNT(*)
----------
   1100098
 
1 row selected.
 
SYS@SANDBOX1> @fsx
Enter value for sql_text: select count(*) from kso.little_skew a
Enter value for sql_id: 
 
SQL_ID         CHILD  PLAN_HASH  EXECS  AVG_ETIME AVG_PX OFFLOAD IO_SAVED_% SQL_TEXT
------------- ------ ---------- ------ ---------- ------ ------- ---------- ----------------------------------------------------------------------
8xrg1nunxn181      0 3498336203      1        .02      0 No             .00 select count(*) from kso.little_skew a
8xrg1nunxn181      1 3498336203      1        .02      0 No             .00 select count(*) from kso.little_skew a
 
2 rows selected.
 
SYS@SANDBOX1> @dplan
Enter value for sql_id: 8xrg1nunxn181
Enter value for child_no: 1
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  8xrg1nunxn181, child number 1
-------------------------------------
select count(*) from kso.little_skew a
 
Plan hash value: 3498336203
 
----------------------------------------------------------------------------------
| Id  | Operation                  | Name        | Rows  | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |             |       |  1546 (100)|          |
|   1 |  SORT AGGREGATE            |             |     1 |            |          |
|   2 |   TABLE ACCESS STORAGE FULL| LITTLE_SKEW |  1100K|  1546   (1)| 00:00:19 |
----------------------------------------------------------------------------------
 
Note
-----
   - SQL profile PROFILE_8xrg1nunxn181_MONITOR used for this statement
 
 
18 rows selected.
 
SYS@SANDBOX1> @report_sql_monitor
Enter value for sid: 
Enter value for sql_id: 8xrg1nunxn181
Enter value for sql_exec_id: 
 
REPORT
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
select count(*) from kso.little_skew a
 
Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  SYS (451:1845)
 SQL ID              :  8xrg1nunxn181
 SQL Execution ID    :  16777217
 Execution Started   :  04/10/2011 19:08:17
 First Refresh Time  :  04/10/2011 19:08:17
 Last Refresh Time   :  04/10/2011 19:08:17
 Duration            :  .020997s
 Module/Action       :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)/-
 Service             :  SYS$USERS
 Program             :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)
 Fetch Calls         :  1
 
Global Stats
======================================
| Elapsed |   Cpu   | Fetch | Buffer |
| Time(s) | Time(s) | Calls |  Gets  |
======================================
|    0.02 |    0.02 |     1 |   5612 |
======================================
 
SQL Plan Monitoring Details (Plan Hash Value=3498336203)
=========================================================================================================================================
| Id |          Operation           |    Name     |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
|    |                              |             | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
=========================================================================================================================================
|  0 | SELECT STATEMENT             |             |         |      |         1 |     +0 |     1 |        1 |          |                 |
|  1 |   SORT AGGREGATE             |             |       1 |      |         1 |     +0 |     1 |        1 |          |                 |
|  2 |    TABLE ACCESS STORAGE FULL | LITTLE_SKEW |      1M | 1546 |         1 |     +0 |     1 |       1M |          |                 |
=========================================================================================================================================

So there you have it. A quick and dirty way to enable Real Time SQL Monitoring on a production statement that wasn’t being monitored by default.

I have really been using this capability a lot lately. Being able to see which steps in a complex plan are offloaded and what wait events are affecting which steps is very useful. The “Activity %” column which shows which steps the statement spent all it’s time on is also pretty helpful. It’s a tool that has moved very close to the top of my bag.

P.S. Greg Rahn has been a proponent of this report for some time and has been blogging about it for several years. Here’s one from Jan of 2008: Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR

7 Comments

  1. John Seaman says:

    Very interesting. Thanks Kerry.

  2. Kumar Ramalingam says:

    Hello Kerry,
    Thanks for the script. I am getting the following error. Have you encountered this or am I missing something here? Please advise.

    11:04:50 SQL> @rep_sql_mon
    Enter value for sid: 124
    old 3: session_id=>nvl(‘&&sid’,sys_context(‘userenv’,’sid’)),
    new 3: session_id=>nvl(’124′,sys_context(‘userenv’,’sid’)),
    old 4: session_serial=>decode(‘&&sid’,null,null,
    new 4: session_serial=>decode(’124′,null,null,
    Enter value for sql_id:
    old 7: sql_id=>’&sql_id’,
    new 7: sql_id=>”,
    Enter value for sql_exec_id:
    old 8: sql_exec_id=>’&sql_exec_id’,
    new 8: sql_exec_id=>”,
    ERROR:
    ORA-01427: single-row subquery returns more than one row

    Thanks

    Kumar

  3. osborne says:

    I have not run into that. The script expects a SQL_ID to be entered or for all values to be left blank (which runs the report for the last long running query issued by this session). Try entering a value for the SQL_ID or leaving all prompts blank.

    Kerry

  4. Kumar Ramalingam says:

    Hello Kerry,
    A question on sql execution times when it is run parallel? Have you tried calculating it via “A-Time” in execution plan or through v$sql? I have several queries running with a parallel degree 2 on some of the big partitioned tables. If I execute one, typically I find two rows in v$sql, one belonging to the QC (possibly) and the other row for the total number of slaves used. In my case, though the line that belongs to the QC (EXECUTIONS 1, PX_SERVER_EXECUTIONS 0) gives the elapsed time more closer to the reality, the one for slaves (in this case I see PX_SERVER_EXECUTIONS 4 and EXECUTIONS 0) is larger than 4 times the response time of the QC.
    I would normally expect the time taken by all the slaves would be closer to the sum of my real response time (or closer to that).
    I may be missing something here. If it is evident to you, please share the information. Appreciate your help through this wonderful blog.

    Regards
    Kumar

  5. osborne says:

    Hi Kumar,

    I’m not sure I am understanding your question on this post. In recent versions of Oracle V$SQL should have only one entry for a parallel query. It should have a correct count for the number of executions (1 per actual execution of the entire query) and should have the correct number of slaves assigned to it in px_servers_executions (i.e. the total number of slaves to work on however many executions were done). The elapsed_time field should have the total elapsed time of all the slaves combined. But I didn’t really talk about any of that in this post. The report_sql_monitor procedure provides an elapsed time in the header of the report which seems to be pretty accurate (at least I haven’t noticed any big discrepancies).

    Kerry

  6. Kumar Ramalingam says:

    Thanks for the response Kerry. Since I could not find an appropriate post I just shot this question here. Yes, I do use OEM’s SQL montioring feature that tells me the time. But I had one case where there was a discrepancy in terms of time taken by one of the slaves was more than the elapsed time (end-user’s view of). That SQL somehow aged out of monitoring ( at least the execution times). I wish I could have cross-verified this before it was flushed.

  7. Kumar Ramalingam says:

    Hi Kerry,
    If I want to ask a question, which page would be more appropriate? I mean I don’t want write in a post that you rarely visit.
    This time I have a question on SQL MONITORING page on OEM. If I move my mouse on the time bars, it gives me two types of information, First Active and Duration.
    Have you noticed it? If yes, how do I interpret it? Thanks for the help.

    Kumar

Leave a Reply