Query Statspack's "SQL ordered by" Sections Over a Time Period

by Jure Bratina on Aug 25, 2020 12:00:00 AM

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

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) ).
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.

No Comments Yet

Let us know what you think

Share this