Finding SQL with Performance changing over time
I upgraded my database a couple of weeks ago and now my users complain their application is slower. They do not provide specifics but they “feel” it is running slower. Sounds familiar?
Every once in a while I get a request that goes like this: “how can I find if some SQL on my database is performing worse over time?”
It is very hard to deal with the ambiguities of some problems like “finding SQL that performs worse or better over time”. But if you simplify the problem and consider for example “Elapsed Time per Execution”, then you can easily produce a script like the one below, which returns a small list of SQL statements that seem to experience either a regression or an improvement over time. It uses linear regression on the ratio between “Elapsed Time per Execution” and its Median per SQL.
Then, If you are suspecting you have some SQL that may have regressed and need a hand to identify them, you can try this script below. It is now part of a small collection of scripts that you can download and use for free out of the cscripts link on the right hand side of this page, under “Downloads”.
---------------------------------------------------------------------------------------- -- -- File name: sql_performance_changed.sql -- -- Purpose: Lists SQL Statements with Elapsed Time per Execution changing over time -- -- Author: Carlos Sierra -- -- Version: 2014/10/31 -- -- Usage: Lists statements that have changed their elapsed time per execution over -- some history. -- Uses the ration between "elapsed time per execution" and the median of -- this metric for SQL statements within the sampled history, and using -- linear regression identifies those that have changed the most. In other -- words where the slope of the linear regression is larger. Positive slopes -- are considered "improving" while negative are "regressing". -- -- Example: @sql_performance_changed.sql -- -- Notes: Developed and tested on 11.2.0.3. -- -- Requires an Oracle Diagnostics Pack License since AWR data is accessed. -- -- To further investigate poorly performing SQL use sqltxplain.sql or sqlhc -- (or planx.sql or sqlmon.sql or sqlash.sql). -- --------------------------------------------------------------------------------------- -- SPO sql_performance_changed.txt; DEF days_of_history_accessed = '31'; DEF captured_at_least_x_times = '10'; DEF captured_at_least_x_days_apart = '5'; DEF med_elap_microsecs_threshold = '1e4'; DEF min_slope_threshold = '0.1'; DEF max_num_rows = '20'; SET lin 200 ver OFF; COL row_n FOR A2 HEA '#'; COL med_secs_per_exec HEA 'Median Secs|Per Exec'; COL std_secs_per_exec HEA 'Std Dev Secs|Per Exec'; COL avg_secs_per_exec HEA 'Avg Secs|Per Exec'; COL min_secs_per_exec HEA 'Min Secs|Per Exec'; COL max_secs_per_exec HEA 'Max Secs|Per Exec'; COL plans FOR 9999; COL sql_text_80 FOR A80; PRO SQL Statements with "Elapsed Time per Execution" changing over time WITH per_time AS ( SELECT h.dbid, h.sql_id, SYSDATE - CAST(s.end_interval_time AS DATE) days_ago, SUM(h.elapsed_time_total) / SUM(h.executions_total) time_per_exec FROM dba_hist_sqlstat h, dba_hist_snapshot s WHERE h.executions_total > 0 AND s.snap_id = h.snap_id AND s.dbid = h.dbid AND s.instance_number = h.instance_number AND CAST(s.end_interval_time AS DATE) > SYSDATE - &&days_of_history_accessed. GROUP BY h.dbid, h.sql_id, SYSDATE - CAST(s.end_interval_time AS DATE) ), avg_time AS ( SELECT dbid, sql_id, MEDIAN(time_per_exec) med_time_per_exec, STDDEV(time_per_exec) std_time_per_exec, AVG(time_per_exec) avg_time_per_exec, MIN(time_per_exec) min_time_per_exec, MAX(time_per_exec) max_time_per_exec FROM per_time GROUP BY dbid, sql_id HAVING COUNT(*) >= &&captured_at_least_x_times. AND MAX(days_ago) - MIN(days_ago) >= &&captured_at_least_x_days_apart. AND MEDIAN(time_per_exec) > &&med_elap_microsecs_threshold. ), time_over_median AS ( SELECT h.dbid, h.sql_id, h.days_ago, (h.time_per_exec / a.med_time_per_exec) time_per_exec_over_med, a.med_time_per_exec, a.std_time_per_exec, a.avg_time_per_exec, a.min_time_per_exec, a.max_time_per_exec FROM per_time h, avg_time a WHERE a.sql_id = h.sql_id ), ranked AS ( SELECT RANK () OVER (ORDER BY ABS(REGR_SLOPE(t.time_per_exec_over_med, t.days_ago)) DESC) rank_num, t.dbid, t.sql_id, CASE WHEN REGR_SLOPE(t.time_per_exec_over_med, t.days_ago) > 0 THEN 'IMPROVING' ELSE 'REGRESSING' END change, ROUND(REGR_SLOPE(t.time_per_exec_over_med, t.days_ago), 3) slope, ROUND(AVG(t.med_time_per_exec)/1e6, 3) med_secs_per_exec, ROUND(AVG(t.std_time_per_exec)/1e6, 3) std_secs_per_exec, ROUND(AVG(t.avg_time_per_exec)/1e6, 3) avg_secs_per_exec, ROUND(MIN(t.min_time_per_exec)/1e6, 3) min_secs_per_exec, ROUND(MAX(t.max_time_per_exec)/1e6, 3) max_secs_per_exec FROM time_over_median t GROUP BY t.dbid, t.sql_id HAVING ABS(REGR_SLOPE(t.time_per_exec_over_med, t.days_ago)) > &&min_slope_threshold. ) SELECT LPAD(ROWNUM, 2) row_n, r.sql_id, r.change, TO_CHAR(r.slope, '990.000MI') slope, TO_CHAR(r.med_secs_per_exec, '999,990.000') med_secs_per_exec, TO_CHAR(r.std_secs_per_exec, '999,990.000') std_secs_per_exec, TO_CHAR(r.avg_secs_per_exec, '999,990.000') avg_secs_per_exec, TO_CHAR(r.min_secs_per_exec, '999,990.000') min_secs_per_exec, TO_CHAR(r.max_secs_per_exec, '999,990.000') max_secs_per_exec, (SELECT COUNT(DISTINCT p.plan_hash_value) FROM dba_hist_sql_plan p WHERE p.dbid = r.dbid AND p.sql_id = r.sql_id) plans, REPLACE((SELECT DBMS_LOB.SUBSTR(s.sql_text, 80) FROM dba_hist_sqltext s WHERE s.dbid = r.dbid AND s.sql_id = r.sql_id), CHR(10)) sql_text_80 FROM ranked r WHERE r.rank_num <= &&max_num_rows. ORDER BY r.rank_num / SPO OFF;
Once you get the output of this script above, you can use the one below to actually list the time series for one of the SQL statements of interest:
---------------------------------------------------------------------------------------- -- -- File name: one_sql_time_series.sql -- -- Purpose: Performance History for one SQL -- -- Author: Carlos Sierra -- -- Version: 2014/10/31 -- -- Usage: Script sql_performance_changed.sql lists SQL Statements with performance -- improvement or regressed over some History. -- This script one_sql_time_series.sql lists the Performance Time Series for -- one SQL. -- -- Parameters: SQL_ID -- -- Example: @one_sql_time_series.sql -- -- Notes: Developed and tested on 11.2.0.3. -- -- Requires an Oracle Diagnostics Pack License since AWR data is accessed. -- -- To further investigate poorly performing SQL use sqltxplain.sql or sqlhc -- (or planx.sql or sqlmon.sql or sqlash.sql). -- --------------------------------------------------------------------------------------- -- SPO one_sql_time_series.txt; SET lin 200 ver OFF; COL instance_number FOR 9999 HEA 'Inst'; COL end_time HEA 'End Time'; COL plan_hash_value HEA 'Plan|Hash Value'; COL executions_total FOR 999,999 HEA 'Execs|Total'; COL rows_per_exec HEA 'Rows Per Exec'; COL et_secs_per_exec HEA 'Elap Secs|Per Exec'; COL cpu_secs_per_exec HEA 'CPU Secs|Per Exec'; COL io_secs_per_exec HEA 'IO Secs|Per Exec'; COL cl_secs_per_exec HEA 'Clus Secs|Per Exec'; COL ap_secs_per_exec HEA 'App Secs|Per Exec'; COL cc_secs_per_exec HEA 'Conc Secs|Per Exec'; COL pl_secs_per_exec HEA 'PLSQL Secs|Per Exec'; COL ja_secs_per_exec HEA 'Java Secs|Per Exec'; SELECT h.instance_number, TO_CHAR(CAST(s.end_interval_time AS DATE), 'YYYY-MM-DD HH24:MI') end_time, h.plan_hash_value, h.executions_total, TO_CHAR(ROUND(h.rows_processed_total / h.executions_total), '999,999,999,999') rows_per_exec, TO_CHAR(ROUND(h.elapsed_time_total / h.executions_total / 1e6, 3), '999,990.000') et_secs_per_exec, TO_CHAR(ROUND(h.cpu_time_total / h.executions_total / 1e6, 3), '999,990.000') cpu_secs_per_exec, TO_CHAR(ROUND(h.iowait_total / h.executions_total / 1e6, 3), '999,990.000') io_secs_per_exec, TO_CHAR(ROUND(h.clwait_total / h.executions_total / 1e6, 3), '999,990.000') cl_secs_per_exec, TO_CHAR(ROUND(h.apwait_total / h.executions_total / 1e6, 3), '999,990.000') ap_secs_per_exec, TO_CHAR(ROUND(h.ccwait_total / h.executions_total / 1e6, 3), '999,990.000') cc_secs_per_exec, TO_CHAR(ROUND(h.plsexec_time_total / h.executions_total / 1e6, 3), '999,990.000') pl_secs_per_exec, TO_CHAR(ROUND(h.javexec_time_total / h.executions_total / 1e6, 3), '999,990.000') ja_secs_per_exec FROM dba_hist_sqlstat h, dba_hist_snapshot s WHERE h.sql_id = '&sql_id.' AND h.executions_total > 0 AND s.snap_id = h.snap_id AND s.dbid = h.dbid AND s.instance_number = h.instance_number ORDER BY h.sql_id, h.instance_number, s.end_interval_time, h.plan_hash_value / SPO OFF;
I really like the IMPROVING/REGRESSING column.. Nice work Carlos.
Stephen Butterworth
November 2, 2014 at 9:11 am
[…] Saw an interesting post related to work I am doing locking in plans and finding plans that have changed: Carlos Sierra post on queries with changing performance. […]
Useful Carlos Sierra post about queries changing performance | Bobby Durrett's DBA Blog
November 3, 2014 at 10:27 am
Awesome scripts Carlos!!
As _total columns are cumulative should SUM(h.elapsed_time_total) / SUM(h.executions_total) be SUM(h.elapsed_time_delta) / SUM(h.executions_delta)?
vishaldesai
November 3, 2014 at 4:49 pm
It could be deltas, but i thing using totals make it more steady.
Carlos Sierra
November 4, 2014 at 6:23 am
thanks Carlos for this nice script collection.
Foued
fouedgray
April 18, 2016 at 12:23 pm
thanks Carlos. Not able to download scripts from RHS. Says page not found. Is it moved somewhere?.
Nen
June 2, 2017 at 8:44 am
Just look at the right-hand side of page, under “Free Downloads” below ORAPeeps. You will see a link that reads “cscripts”
Carlos Sierra
June 2, 2017 at 12:02 pm
[…] Finding SQL with Performance changing over time […]
Finding SQL with Performance changing over time..!! – Enmotech Blog
May 23, 2018 at 4:42 am
Hey,
Maybe I wrong, but when I try to manually create a table with some values from 1 1 1 1 4 5 and 111 on the end it would be ‘5’ positive for the slope, not negative. Although there is in your query, this slope should be Improving not regressing, but I guess it should be Regressing. I mean here:
CASE WHEN REGR_SLOPE(t.time_per_exec_over_med, t.days_ago) > 0 THEN ‘IMPROVING’ ELSE ‘REGRESSING’ END change
ereee
September 7, 2018 at 10:20 am
I see your point. Yes, this could be a false positive. What do you suggest?
Carlos Sierra
September 10, 2018 at 7:16 am
[…] https://carlos-sierra.net/2014/11/02/finding-sql-with-performance-changing-over-time/ […]
Database Migration/Upgrade – Performance Advice – DBA BRASIL
September 12, 2022 at 8:00 am