Query Statspack’s “SQL ordered by” Sections Over a Time Period

Posted in: Oracle, Technical Track

In this post, I’ll present the statspack_top_sqls.sql script, which returns SQL performance statistics by mining the Statspack repository. In a previous blog post, I presented the statspack_load_trends.sql and the AWR_load_trends.sql scripts, which provide a high-level overview of workload dynamics on DB instance(s) over time.

The statspack_top_sqls.sql script provides the same SQLs with the same performance statistics as in Statspack’s various “SQL ordered by” sections. However, it does so by reporting the figures of all categories in a single line. More importantly, it provides this information over a time range, considering each available consecutive pair of snapshots. This provides a way to quickly identify SQLs contributing the most to a particular “SQL ordered by” category over a time period. Alternatively, we can also check for specific SQL(s) behavior over time.

The core logic of the statspack_top_sqls.sql script is based on Oracle’s $ORACLE_HOME/rdbms/admin/sprepins.sql (StatsPack Report Instance) script, but it doesn’t rely on its existence to run. Similarly, to statspack_load_trends.sql, it queries the Statspack repository directly. It doesn’t create or use any (temporary) objects; not even the global temporary table that sprepins.sql uses when producing the report. We can also use the script to analyze a repository imported from another DB, and it can handle periods spanning instance restart(s).

An important note in case you want to compare the results with Statspack reports

Testing the script by comparing its output to regular Statspack reports (created by running $ORACLE_HOME/rdbms/admin/spreport.sql or sprepins.sql), I noticed that sometimes the numbers in the “SQL ordered by” sections didn’t match up. Examples include SQLs reported by my script, but not by Statspack reports. This even happened with Statspack reports reporting the same SQL (same hash value) multiple times with different runtime statistics in the same “SQL ordered by” section.
The root cause of those anomalies is described in the MOS note “Statspack Reports Show Different Results In ‘SQL ordered by …’ When Taken At Different Times with Same Snapid (Doc ID 2258762.1)”: “When more than one statspack reports are taken repeatedly in the same session by non-perfstat user, some data might get mixed up in the temporary table used by the reporting script, and the result may get corrupted.

Not connecting as the owner of the Statspack repository (usually PERFSTAT) when generating multiple consecutive snapshots looping over a snapshot range causes this problem. The same was true also when creating a single Statspack report.

The takeaway is to always connect as the Statspack repository owner when running spreport.sql, especially if you use any helper scripts which generate Statspack reports for a series of snapshots.

Usage

Starting the script

Let’s see the script in action analyzing a sample Swingbench run on a sandbox 2 node RAC database. When run, the script produces a wide output, so I suggest spooling it to a file for easier viewing/plotting:

SQL> spool top_sqls.txt
SQL> @statspack_top_sqls.sql

List SQL by [elapsed_time | cpu_time | buffer_gets | disk_reads | executions | parse_calls | max_sharable_mem | max_version_count | cluster_wait_time]:

Enter a value - default "elapsed_time" :

First, we specify which category we want the SQLs to be ordered by. We can choose one of the above-listed possibilities, which are the same categories the “SQL ordered by” Statspack report’s sections display. The script reports the same SQLs in the same order as they appear in the selected Statspack report category.

Suppose we want to order SQLs by “cpu_time,” and the corresponding Statspack report lists 10 SQLs in the “SQL ordered by CPU” section. The script lists the same ones. However, the added benefit of the script is that it reports values, which the Statspack report doesn’t display. For example, the “SQL ordered by CPU” Statspack report section doesn’t display the “Physical Reads” statistic. Instead, it’s listed in the “SQL ordered by Elapsed time” section. If an SQL isn’t qualified to display in the “SQL ordered by Elapsed time” section, we won’t get those values from the Statspack report.

Next, we provide the DBID and instance number we want to analyze. If we don’t provide an instance number, the script considers all those present in the repository:

Instances in this Statspack schema
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
   DB Id    Inst Num DB Name      Instance     Host
----------- -------- ------------ ------------ --------------------------------
 1558102526        1 ORCL         orcl1        ol7-122-rac1.localdomain
 1558102526        2 ORCL         orcl2        ol7-122-rac2.localdomain


Enter DBID to analyze - default "1558102526" :
Enter instance number or "all" to analyze all instancs for DBID = 1558102526 - default "all" :

Finally, we specify the time range we’d like to analyze:

Enter begin time for report [DD-MON-YYYY HH24:MI] - default "30-APR-2020 10:54" : 15-FEB-2020 12:30
Enter end time for report [DD-MON-YYYY HH24:MI] - default "30-APR-2020 22:54" : 15-FEB-2020 13:00

Script output

Let’s check what the script output looks like on an example where SQLs are ordered by “elapsed_time.” For reference, a file containing the whole spool can be obtained here, and two Statspack reports covering the snapshots discussed below are here and here.

Since the original spool file contains 280 lines, I’m showing an abbreviated version of the first eight columns. The full output lists SQLs between each snapshot. As we didn’t specify which instance number we’re interested in, both instances are considered. Additionally, we see it’s normal and expected, that consecutive snapshots don’t have consecutive numbers. Snapshots 4 and 21 are two consecutive snapshots on instance 1, as we can confirm by checking their snap time. The other columns are self-explanatory:

INSTANCE_NUMBER  B_SNAP_ID  E_SNAP_ID B_SNAP_TIME        E_SNAP_TIME        INTERVAL_MIN  DBTIMEMIN        AAS
--------------- ---------- ---------- ------------------ ------------------ ------------ ---------- ----------
              1          1          2 15-FEB-20 12:30:00 15-FEB-20 12:40:00           10       2.30       0.23
                                                                                                               <removed 16 lines listing SQLs>
                         2          3 15-FEB-20 12:40:00 15-FEB-20 12:50:00           10       1.60       0.16
                                                                                                               <removed 25 lines listing SQLs>
                         3          4 15-FEB-20 12:50:00 15-FEB-20 13:00:00           10       1.55       0.15
                                                                                                               <etc>
                         4         21 15-FEB-20 13:00:00 15-FEB-20 13:10:00           10       1.66       0.17

                        21         22 15-FEB-20 13:10:00 15-FEB-20 13:20:00           10       1.30       0.13

                        22         23 15-FEB-20 13:20:00 15-FEB-20 13:30:00           10       1.18       0.12

              2         11         12 15-FEB-20 12:30:00 15-FEB-20 12:40:00           10       3.81       0.38

                        12         13 15-FEB-20 12:40:00 15-FEB-20 12:50:00           10       2.70       0.27

                        13         14 15-FEB-20 12:50:00 15-FEB-20 13:00:00           10       2.50       0.25

                        14         15 15-FEB-20 13:00:00 15-FEB-20 13:10:00           10       2.94       0.29

                        15         16 15-FEB-20 13:10:00 15-FEB-20 13:20:00           10       2.18       0.22

                        16         17 15-FEB-20 13:20:00 15-FEB-20 13:30:00           10       1.98       0.20

Let’s check an excerpt of the output for snapshots 1 to 2 and 2 to 3. Apart from the “HV” column (SQL old hash value), the other columns are self-explanatory. For blog post brevity, I’m showing only the first 10 SQLs per snapshot pair.

 B_SNAP_ID  E_SNAP_ID         HV ELAPSED_TIME_SEC EXECUTIONS ELAPSED_PER_EXEC_SEC PERCENT_OF_DBTIME_USED CPU_TIME_SEC CPU_TIME_MS_PER_EXEC PHYSICAL_READS PHYSICAL_READS_PER_EXECUTION BUFFER_GETS GETS_PER_EXECUTION ROWS_PROCESSED ROWS_PROCESSED_PER_EXECUTION PARSE_CALLS MAX_SHARABLE_MEM_KB LAST_SHARABLE_MEM_KB MAX_VERSION_COUNT LAST_VERSION_COUNT DELTA_VERSION_COUNT CLUSTER_WAIT_TIME_SEC CWT_PERCENT_OF_ELAPSED_TIME AVG_HARD_PARSE_TIME_MS MODULE                                                       SQL_TEXT
---------- ---------- ---------- ---------------- ---------- -------------------- ---------------------- ------------ -------------------- -------------- ---------------------------- ----------- ------------------ -------------- ---------------------------- ----------- ------------------- -------------------- ----------------- ------------------ ------------------- --------------------- --------------------------- ---------------------- ------------------------------------------------------------ ---------------------------------------------------------------------------
         1          2 3565022785            80,55        483                  ,17                  58,47        14,63                 30,3           5860                        12,13      261329             541,05            483                            1         483               55,39                55,39                 1                  1                   1                 13,67                       16,97                        JDBC Thin Client                                             BEGIN :1 := orderentry.neworder(:2 ,:3 ,:4 ); END;
                      2319948924             55,8       5931                  ,01                  40,51         7,69                  1,3           4614                          ,78      205925              34,72          26467                         4,46           1               47,44                47,44                 1                  1                   1                  9,38                        16,8                        New Order                                                    SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, C
                      1852190137            14,22       1024                  ,01                  10,32         7,75                 7,57            394                          ,38      131100             128,03           1024                            1        1025               55,38                55,38                 1                  1                   1                  2,65                       18,61                                                                                     BEGIN :1 := orderentry.browseproducts(:2 ,:3 ,:4 ); END;
                      1113394757             8,17      12332                    0                   5,93         2,97                  ,24            336                          ,03      124291              10,08         172648                           14           1               43,41                43,41                 1                  1                   1                  2,17                       26,55                        Browse Products                                              SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, C
                      4194254847              6,4        483                  ,01                   4,64          ,84                 1,73            396                          ,82        7760              16,07            483                            1           1               47,64                47,64                 1                  1                   1                  1,26                       19,72                        New Order                                                    INSERT INTO ORDERS ( ORDER_ID, ORDER_DATE, ORDER_MODE, CUSTOMER_
                      1283549268             4,55        169                  ,03                    3,3          ,89                 5,28            262                         1,55        6188              36,62            169                            1         169               59,46                59,46                 1                  1                   1                   ,83                       18,16                                                                                     BEGIN :1 := orderentry.newcustomer(:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:
                      2588369535             4,21         24                  ,18                   3,06         1,12                46,55             76                         3,17       13104                546             24                            1          24               55,38                55,38                 1                  1                   1                  2,21                       52,52                                                                                     BEGIN :1 := orderentry.SalesRepsQuery(:2 ,:3 ,:4 ); END;
                      4212635381             4,18         24                  ,17                   3,04         1,09                45,39             76                         3,17       13104                546            737                        30,71           1               35,51                35,51                 1                  1                   1                  2,21                        52,9                        Sales Rep Query                                              SELECT TT.ORDER_TOTAL, TT.SALES_REP_ID, TT.ORDER_DATE, CUSTOMERS
                      4219272024             3,97       1396                    0                   2,88          ,86                  ,62            167                          ,12       19979              14,31           1396                            1           1               27,42                27,42                 1                  1                   1                  1,15                       28,85                        New Order                                                    INSERT INTO ORDER_ITEMS ( ORDER_ID, LINE_ITEM_ID, PRODUCT_ID, UN
                      2835506982             3,74        173                  ,02                   2,71          ,57                 3,32            255                         1,47        3579              20,69            173                            1         173               55,38                55,38                 1                  1                   1                   ,39                       10,53                                                                                     BEGIN :1 := orderentry.browseandupdateorders(:2 ,:3 ,:4 ); END;
                      (..)
					  
         2          3 3565022785            46,93        956                  ,05                  48,79        18,87                19,73           1138                         1,19      511742             535,29            956                            1         957              113,27               113,27                 2                  2                   1                 15,91                       33,89                        JDBC Thin Client                                             BEGIN :1 := orderentry.neworder(:2 ,:3 ,:4 ); END;
                      2319948924            22,85      11550                    0                  23,75         7,52                  ,65            487                          ,04      402425              34,84          51879                         4,49           0               47,44                47,44                 1                  1                   0                     9                       39,39                        New Order                                                    SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, C
                      1852190137            15,35       2158                  ,01                  15,95        11,98                 5,55            164                          ,08      274493              127,2           2158                            1        2157              113,25               113,25                 2                  2                   1                  1,32                        8,63                                                                                     BEGIN :1 := orderentry.browseproducts(:2 ,:3 ,:4 ); END;
                      1283549268             6,36        380                  ,02                   6,61         1,65                 4,33            303                           ,8       13726              36,12            380                            1         380              121,42               121,42                 2                  2                   1                  1,42                       22,26                                                                                     BEGIN :1 := orderentry.newcustomer(:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:
                      2835506982                6        377                  ,02                   6,24         1,03                 2,72            448                         1,19        7218              19,15            377                            1         377              113,27               113,27                 2                  2                   1                   ,72                       12,06                                                                                     BEGIN :1 := orderentry.browseandupdateorders(:2 ,:3 ,:4 ); END;
                      1822227481             5,32       7742                    0                   5,53         1,26                  ,16            259                          ,03       23226                  3           7742                            1           0                31,5                 31,5                 1                  1                   0                   1,5                       28,14                        New Order                                                    SELECT CUSTOMER_ID, CUST_FIRST_NAME, CUST_LAST_NAME, NLS_LANGUAG
                      4194254847             4,69        957                    0                   4,87         1,22                 1,28            150                          ,16       14371              15,02            957                            1           0               47,64                47,64                 1                  1                   0                  1,76                       37,54                        New Order                                                    INSERT INTO ORDERS ( ORDER_ID, ORDER_DATE, ORDER_MODE, CUSTOMER_
                      3463613875             4,61        380                  ,01                   4,79          ,62                 1,62            298                          ,78        5844              15,38            380                            1           0               59,63                59,63                 1                  1                   0                   ,81                       17,49                        Update Customer Details                                      INSERT INTO CUSTOMERS ( CUSTOMER_ID , CUST_FIRST_NAME , CUST_LAS
                      1113394757             4,07      25794                    0                   4,23         3,28                  ,13              0                            0      260084              10,08         361116                           14           0               43,41                43,41                 1                  1                   0                   ,41                        9,98                        Browse Products                                              SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, C
                      4219272024             3,89       2945                    0                   4,04         1,43                  ,49             76                          ,03       42277              14,36           2945                            1           0               27,42                27,42                 1                  1                   0                  1,77                       45,53                        New Order                                                    INSERT INTO ORDER_ITEMS ( ORDER_ID, LINE_ITEM_ID, PRODUCT_ID, UN
                      (..)

Let’s check how a regular Statspack report covering snapshot IDs 1 to 2 looks compared to the above output. The report’s “SQL ordered by Elapsed time” section reports the same SQLs in the same order as in the above excerpt. The difference is that the latter displays attributes from other “SQL ordered by” sections which are not present in the below output:

Snapshot       Snap Id     Snap Time      
~~~~~~~~    ---------- ------------------ 
Begin Snap:          1 15-Feb-20 12:30:00 
  End Snap:          2 15-Feb-20 12:40:00 
   Elapsed:      10.00 (mins) 
   DB time:       2.30 (mins) 

Load Profile              Per Second    
~~~~~~~~~~~~      ------------------  
      DB time(s):                0.2  


SQL ordered by Elapsed time for DB: ORCL  Instance: orcl1  Snaps: 1 -2
-> Total DB Time (s):             138
-> Captured SQL accounts for  153.3% of Total DB Time
-> SQL reported below exceeded  1.0% of Total DB Time

  Elapsed                Elap per            CPU                        Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)  Physical Reads Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
     80.55          483       0.17   58.5      14.63           5,860 3565022785
Module: JDBC Thin Client
BEGIN :1 := orderentry.neworder(:2 ,:3 ,:4 ); END;

     55.80        5,931       0.01   40.5       7.69           4,614 2319948924
Module: New Order
SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, C
ATEGORY_ID, WEIGHT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID, PRODUCT_
STATUS, LIST_PRICE, MIN_PRICE, CATALOG_URL, QUANTITY_ON_HAND FRO
M PRODUCTS, INVENTORIES WHERE PRODUCTS.CATEGORY_ID = :B3 AND INV

     14.22        1,024       0.01   10.3       7.75             394 1852190137
BEGIN :1 := orderentry.browseproducts(:2 ,:3 ,:4 ); END;

      8.17       12,332       0.00    5.9       2.97             336 1113394757
Module: Browse Products
SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, C
ATEGORY_ID, WEIGHT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID, PRODUCT_
STATUS, LIST_PRICE, MIN_PRICE, CATALOG_URL, QUANTITY_ON_HAND FRO
M PRODUCTS, INVENTORIES WHERE PRODUCTS.PRODUCT_ID = :B2 AND INVE

      6.40          483       0.01    4.6       0.84             396 4194254847
Module: New Order
INSERT INTO ORDERS ( ORDER_ID, ORDER_DATE, ORDER_MODE, CUSTOMER_
ID, ORDER_STATUS, WAREHOUSE_ID, DELIVERY_TYPE, DELIVERY_ADDRESS_
ID, COST_OF_DELIVERY, WAIT_TILL_ALL_AVAILABLE, CUSTOMER_CLASS, C
ARD_ID, INVOICE_ADDRESS_ID ) VALUES ( ORDERS_SEQ.NEXTVAL + :B8 ,

      4.55          169       0.03    3.3       0.89             262 1283549268
BEGIN :1 := orderentry.newcustomer(:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:
9 ,:10 ); END;

      4.21           24       0.18    3.1       1.12              76 2588369535
BEGIN :1 := orderentry.SalesRepsQuery(:2 ,:3 ,:4 ); END;

      4.18           24       0.17    3.0       1.09              76 4212635381
Module: Sales Rep Query
SELECT TT.ORDER_TOTAL, TT.SALES_REP_ID, TT.ORDER_DATE, CUSTOMERS
.CUST_FIRST_NAME, CUSTOMERS.CUST_LAST_NAME FROM (SELECT ORDERS.O
RDER_TOTAL, ORDERS.SALES_REP_ID, ORDERS.ORDER_DATE, ORDERS.CUSTO
MER_ID, RANK() OVER (ORDER BY ORDERS.ORDER_TOTAL DESC) SAL_RANK

      3.97        1,396       0.00    2.9       0.86             167 4219272024
Module: New Order
INSERT INTO ORDER_ITEMS ( ORDER_ID, LINE_ITEM_ID, PRODUCT_ID, UN
IT_PRICE, QUANTITY, GIFT_WRAP, CONDITION, ESTIMATED_DELIVERY ) V
ALUES ( :B4 , :B3 , :B2 , :B1 , 1, 'None', 'New', (SYSDATE + 3)
)

      3.74          173       0.02    2.7       0.57             255 2835506982
BEGIN :1 := orderentry.browseandupdateorders(:2 ,:3 ,:4 ); END; 

(..)

Final notes

  1. Oracle’s sprepins.sql script has a /*+ first_rows */ hint in the inline view containing analytical functions used to compute the current and previous row values from the stats$sql_summary table. The hint is present, but not enabled in statspack_top_sqls.sql. If, for some reason, you need to re-enable it, just search for and enable it in the script (or use its alternative first_rows(0) ).
  2. I’ve seen the script fail with errors like “ORA-00936: missing expression,” or “ORA-01722: invalid number” when used on databases running with cursor_sharing=FORCE. To avoid the error, I included the /*+ cursor_sharing_exact*/ hint in the script’s SELECT statement. Setting cursor_sharing=EXACT at the session-level is also a valid alternative.
email

Authors

Interested in working with Jure? Schedule a tech call.

About the Author

Oracle Database Consultant
Jure Bratina is an experienced Oracle DBA currently working as a Database Consultant with The Pythian Group. The areas he most likes to work on are troubleshooting and performance tuning of Oracle databases. Jure is also a member of the Executive Committee at the Slovenian Oracle User Group (SIOUG).

No comments

Leave a Reply

Your email address will not be published. Required fields are marked *