Saturday, April 14, 2012

Analyzing the last query run

I don't know how many times I find myself trying to tune a query, and going through the same tasks.

I run the sql in my session (most likely on sqlplus on the unix server), but I then try to track down the sql_id, and finally (if I am lucky) find the SQL Monitor report (tuning pack license required).

So I came up with a script that I am putting on all my severs. post_execute.sql

This script can be executed in your shell as the next step after running the query in question.. but first.

If you want to use the SQL Monitor output, you are best adding the /*+monitor */ hint to your query just to be sure it is captured.

Well this is what the script does.

1) run your query.. I used this query for my example.


select /*+monitor */ a.owner,b.table_name ,sum(bytes) from dba_segments a,
                                     dba_tables b
where a.owner=b.owner and 
      a.segment_name=b.table_name 
group by a.owner,b.table_name
order by a.owner,b.table_name;


2) It captures the dbms_xplan.display_cursor output for the last run sql.. Here is snippet of what the output looked like..

Plan information for current query




SQL_ID  208ttrm2nbt0u, child number 0
-------------------------------------
select /*+monitor */ a.owner,b.table_name ,sum(bytes) from dba_segments 
a,                                      dba_tables b where 
a.owner=b.owner and       a.segment_name=b.table_name group by 
a.owner,b.table_name order by a.owner,b.table_name
 
Plan hash value: 1601540958
 
--------------------------------------------------------------------------------------------------------------
| Id  | Operation                                   | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                            |                |       |       | 14425 (100)|          |
|   1 |  SORT GROUP BY                              |                |     6 |  2184 | 14425   (1)| 00:02:54 |
|*  2 |   HASH JOIN OUTER                           |                |     6 |  2184 | 14424   (1)| 00:02:54 |
|   3 |    NESTED LOOPS OUTER                       |                |     6 |  2160 | 14422   (1)| 00:02:54 |
|   4 |     NESTED LOOPS OUTER                      |                |     6 |  2106 | 14410   (1)| 00:02:53 |
|   5 |      NESTED LOOPS OUTER                     |                |     6 |  2070 | 14408   (1)| 00:02:53 |
|   6 |       NESTED LOOPS                          |                |     6 |  1998 | 14396   (1)| 00:02:53 |
|   7 |        NESTED LOOPS                         |                |     6 |  1974 | 14390   (1)| 00:02:53 |
|*  8 |         HASH JOIN                           |                |    67 | 19899 | 14318   (1)| 00:02:52 |
|*  9 |          HASH JOIN                          |                |  5095 |  1298K| 13638   (1)| 00:02:44 |
|  10 |           MERGE JOIN CARTESIAN              |                |   131 | 11135 |     5  (20)| 00:00:01 |
|* 11 |            HASH JOIN                        |                |     1 |    68 |     1 (100)| 00:00:01 |
|* 12 |             FIXED TABLE FULL                | X$KSPPI        |     1 |    55 |     0   (0)|          |
|  13 |             FIXED TABLE FULL                | X$KSPPCV       |   100 |  1300 |     0   (0)|          |
|  14 |            BUFFER SORT                      |                |   131 |  2227 |     5  (20)| 00:00:01 |
|  15 |             TABLE ACCESS STORAGE FULL       | USER$          |   131 |  2227 |     4   (0)| 00:00:01 |
|  16 |           VIEW                              | SYS_DBA_SEGS   |  5095 |   875K| 13633   (1)| 00:02:44 |
|  17 |            UNION-ALL                        |                |       |       |            |          |
|* 18 |             HASH JOIN RIGHT OUTER           |                |   672 |   103K| 12305   (1)| 00:02:28 |
|  19 |              TABLE ACCESS STORAGE FULL      | USER$          |   131 |  2227 |     4   (0)| 00:00:01 |
|* 20 |              HASH JOIN                      |                |   672 | 94752 | 12301   (1)| 00:02:28 |
|  21 |               NESTED LOOPS                  |                |   672 | 68544 | 11623   (1)| 00:02:20 |
|* 22 |                HASH JOIN                    |                |   672 | 63168 | 11623   (1)| 00:02:20 |
|  23 |                 TABLE ACCESS STORAGE FULL   | TS$            |   167 |  1336 |    48   (0)| 00:00:01 |
|* 24 |                 HASH JOIN                   |                |   672 | 57792 | 11574   (1)| 00:02:19 |
|  25 |                  TABLE ACCESS STORAGE FULL  | SEG$           | 16421 |   449K|   821   (1)| 00:00:10 |
|  26 |                  VIEW                       | SYS_OBJECTS    | 21369 |  1210K| 10752   (1)| 00:02:10 |
|  27 |                   UNION-ALL                 |                |       |       |            |          |
|* 28 |                    TABLE ACCESS STORAGE FULL| TAB$           |  7284 |   177K|  2681   (1)| 00:00:33 |
|  29 |                    TABLE ACCESS STORAGE FULL| TABPART$       |  1525 | 28975 |    12   (0)| 00:00:01 |
|  30 |                    TABLE ACCESS STORAGE FULL| CLU$           |    10 |   140 |  2680   (1)| 00:00:33 |
|* 31 |                    TABLE ACCESS STORAGE FULL| IND$           |  9647 |   188K|  2681   (1)| 00:00:33 |
|  32 |                    TABLE ACCESS STORAGE FULL| INDPART$       |  1322 | 25118 |    12   (0)| 00:00:01 |
|* 33 |                    TABLE ACCESS STORAGE FULL| LOB$           |  1547 | 32487 |  2680   (1)| 00:00:33 |
|  34 |                    TABLE ACCESS STORAGE FULL| TABSUBPART$    |    32 |   448 |     2   (0)| 00:00:01 |
|  35 |                    TABLE ACCESS STORAGE FULL| INDSUBPART$    |     1 |    52 |     2   (0)| 00:00:01 |
|  36 |                    TABLE ACCESS STORAGE FULL| LOBFRAG$       |     1 |    17 |     2   (0)| 00:00:01 |
|* 37 |                INDEX UNIQUE SCAN            | I_FILE2        |     1 |     8 |     0   (0)|          |
|  38 |               TABLE ACCESS STORAGE FULL     | OBJ$           | 88138 |  3356K|   677   (1)| 00:00:09 |
|  39 |             NESTED LOOPS                    |                |    34 |  3638 |   450   (1)| 00:00:06 |
|  40 |              NESTED LOOPS                   |                |    34 |  3366 |   450   (1)| 00:00:06 |
|* 41 |               HASH JOIN OUTER               |                |    34 |  3094 |   416   (1)| 00:00:05 |
|  42 |                NESTED LOOPS                 |                |    34 |  2516 |   411   (0)| 00:00:05 |
|* 43 |                 TABLE ACCESS STORAGE FULL   | UNDO$          |   204 |  8568 |     3   (0)| 00:00:01 |
|* 44 |                 TABLE ACCESS CLUSTER        | SEG$           |     1 |    32 |     2   (0)| 00:00:01 |
|* 45 |                  INDEX UNIQUE SCAN          | I_FILE#_BLOCK# |     1 |       |     1   (0)| 00:00:01 |
|  46 |                TABLE ACCESS STORAGE FULL    | USER$          |   131 |  2227 |     4   (0)| 00:00:01 |
|  47 |               TABLE ACCESS CLUSTER          | TS$            |     1 |     8 |     1   (0)| 00:00:01 |
|* 48 |                INDEX UNIQUE SCAN            | I_TS#          |     1 |       |     0   (0)|          |
|* 49 |              INDEX UNIQUE SCAN              | I_FILE2        |     1 |     8 |     0   (0)|          |
|* 50 |             HASH JOIN                       |                |  4389 |   321K|   878   (1)| 00:00:11 |
|  51 |              TABLE ACCESS STORAGE FULL      | FILE$          |   569 |  6828 |     3   (0)| 00:00:01 |
|* 52 |              HASH JOIN RIGHT OUTER          |                |  4389 |   270K|   874   (1)| 00:00:11 |
|  53 |               TABLE ACCESS STORAGE FULL     | USER$          |   131 |  2227 |     4   (0)| 00:00:01 |
|* 54 |               HASH JOIN                     |                |  4389 |   197K|   870   (1)| 00:00:11 |
|  55 |                TABLE ACCESS STORAGE FULL    | TS$            |   167 |  1336 |    48   (0)| 00:00:01 |
|* 56 |                TABLE ACCESS STORAGE FULL    | SEG$           |  4389 |   162K|   821   (1)| 00:00:10 |
|* 57 |          TABLE ACCESS STORAGE FULL          | OBJ$           | 88138 |  3098K|   679   (1)| 00:00:09 |
|* 58 |         TABLE ACCESS CLUSTER                | TAB$           |     1 |    32 |     2   (0)| 00:00:01 |
|* 59 |          INDEX UNIQUE SCAN                  | I_OBJ#         |     1 |       |     1   (0)| 00:00:01 |
|  60 |        TABLE ACCESS CLUSTER                 | TS$            |     1 |     4 |     1   (0)| 00:00:01 |
|* 61 |         INDEX UNIQUE SCAN                   | I_TS#          |     1 |       |     0   (0)|          |
|  62 |       TABLE ACCESS CLUSTER                  | SEG$           |     1 |    12 |     2   (0)| 00:00:01 |
|* 63 |        INDEX UNIQUE SCAN                    | I_FILE#_BLOCK# |     1 |       |     1   (0)| 00:00:01 |
|* 64 |      INDEX RANGE SCAN                       | I_OBJ1         |     1 |     6 |     2   (0)| 00:00:01 |
|* 65 |     INDEX RANGE SCAN                        | I_OBJ1         |     1 |     9 |     2   (0)| 00:00:01 |
|  66 |    INDEX FULL SCAN                          | I_USER2        |   131 |   524 |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - access("CX"."OWNER#"="CU"."USER#")
   8 - access("SEGMENT_NAME"="O"."NAME" AND "O"."OWNER#"="U"."USER#")
   9 - access("OWNER"="U"."NAME")
  11 - access("KSPPI"."INDX"="KSPPCV"."INDX")
  12 - filter("KSPPI"."KSPPINM"='_dml_monitoring_enabled')
  18 - access("O"."OWNER#"="U"."USER#")
  20 - access("O"."OBJ#"="SO"."OBJECT_ID" AND "O"."TYPE#"="SO"."OBJECT_TYPE_ID")
  22 - access("S"."TS#"="TS"."TS#")
  24 - access("S"."FILE#"="SO"."HEADER_FILE" AND "S"."BLOCK#"="SO"."HEADER_BLOCK" AND 
              "S"."TS#"="SO"."TS_NUMBER" AND "S"."TYPE#"="SO"."SEGMENT_TYPE_ID")
  28 - filter(BITAND("T"."PROPERTY",1024)=0)
  31 - filter(("I"."TYPE#"=1 OR "I"."TYPE#"=2 OR "I"."TYPE#"=3 OR "I"."TYPE#"=4 OR "I"."TYPE#"=6 OR 
              "I"."TYPE#"=7 OR "I"."TYPE#"=8 OR "I"."TYPE#"=9))
  33 - filter((BITAND("L"."PROPERTY",64)=0 OR BITAND("L"."PROPERTY",128)=128))
  37 - access("S"."TS#"="F"."TS#" AND "S"."FILE#"="F"."RELFILE#")
  41 - access("S"."USER#"="U"."USER#")
  43 - storage("UN"."STATUS$"<>1)
       filter("UN"."STATUS$"<>1)
  44 - filter(("S"."TYPE#"=1 OR "S"."TYPE#"=10))
  45 - access("S"."TS#"="UN"."TS#" AND "S"."FILE#"="UN"."FILE#" AND "S"."BLOCK#"="UN"."BLOCK#")
  48 - access("S"."TS#"="TS"."TS#")
  49 - access("UN"."TS#"="F"."TS#" AND "UN"."FILE#"="F"."RELFILE#")
  50 - access("S"."TS#"="F"."TS#" AND "S"."FILE#"="F"."RELFILE#")
  52 - access("S"."USER#"="U"."USER#")
  54 - access("S"."TS#"="TS"."TS#")
  56 - filter(("S"."TYPE#"<>6 AND "S"."TYPE#"<>5 AND "S"."TYPE#"<>8 AND "S"."TYPE#"<>10 AND 
              "S"."TYPE#"<>1))
  57 - storage(BITAND("O"."FLAGS",128)=0)
       filter(BITAND("O"."FLAGS",128)=0)
  58 - filter(BITAND("T"."PROPERTY",1)=0)
  59 - access("O"."OBJ#"="T"."OBJ#")
  61 - access("T"."TS#"="TS"."TS#")
  63 - access("T"."TS#"="S"."TS#" AND "T"."FILE#"="S"."FILE#" AND "T"."BLOCK#"="S"."BLOCK#")
  64 - access("T"."BOBJ#"="CO"."OBJ#")
  65 - access("T"."DATAOBJ#"="CX"."OBJ#")

3) It captures some execution statistics that I like to look at .. Here is the output below.





Summary of query stats





 ************** plan_hash_value       = 1188305021
 ************** sql_id               = 208ttrm2nbt0u

avg_elapsed_time      = 2.59
total_executions      = 2
avg_rows_processed    = 5372
avg_disk_reads        = 202
avg_buffer_gets       = 189970
avg_cpu_time          = 2426631
avg_iowait            = 99965
avg_cluster_wait      = 245947
avg_direct_writes     = 0
avg_plssql_exec_time  = 162398
avg_cell_offload      = 0



And finally it creates the beautiful sql_monitor output we are all used to.


Pretty cool huh ?  It creates these 3 pieces based on the last sql executed in the session.. Now this is the best part.. At the end of the script is this code.

!echo "From: bryan.grenn@oracle.com"  > /tmp/file
!echo "To: bryan.grenn@oracle.com"   >> /tmp/file
!echo "Subject: analyze output sql_monitor"   >> /tmp/file
!echo "Mime-Version: 1.0"      >> /tmp/file
!echo 'Content-Type: multipart/mixed; boundary="DMW.Boundary.605592468"'   >> /tmp/file
!echo "--DMW.Boundary.605592468" >> /tmp/file
!echo " " >> /tmp/file
!echo " analyze report sql_monitor " >> /tmp/file
!echo " " >> /tmp/file
!echo "--DMW.Boundary.605592468" >> /tmp/file
!echo 'Content-Disposition: inline; filename="analyze_dbms_xplan.txt"' >> /tmp/file
!echo "Content-Transfer-Encoding: 7bit" >> /tmp/file
!cat /tmp/analyze_dbms_xplan.txt >> /tmp/file
!echo "--DMW.Boundary.605592468" >> /tmp/file

!echo 'Content-Disposition: inline; filename="analyze_query_stats.txt"' >> /tmp/file
!echo "Content-Transfer-Encoding: 7bit" >> /tmp/file
!cat /tmp/analyze_query_stats.txt >> /tmp/file
!echo "--DMW.Boundary.605592468" >> /tmp/file

!echo 'Content-Disposition: inline; filename="analyze_sql_monitor.htm"' >> /tmp/file
!echo "Content-Transfer-Encoding: 7bit" >> /tmp/file
!cat /tmp/analyze_html.htm >> /tmp/file
!echo "--DMW.Boundary.605592468" >> /tmp/file

!/usr/sbin/sendmail bryan.grenn@oracle.com < /tmp/file



This code will take the 3 output files, and mail them to you as attachments.  Notice my e-mail is in the script, so change it to what you need to get it going.  

I'm going to use the often, by putting it on all my servers and just running it after any stubborn sql show up. I will be instantly e-mailed the mail pieces I need to figure out what is going on with the sql.