Monitoring a SQL that executes well thousands of times but sometimes it takes longer
Problem Description
There is this SQL that is constantly executed by many users. This SQL executes in a subsecond thousands of times per day. Every once in a while the same SQL takes several seconds but these incidents are uncommon. Tracing would cause significant overhead since there is no known way to predict when an execution may take longer. In this scenario the concern is finding the root cause of these elusive spikes in the performance of this SQL.
Strategy
Use SQL Monitor report to watch for any SQL that takes longer than a few seconds. Then produce a comprehensive report that would bring some initial light to these spikes. The challenge is to capture this information 24×7 without imposing a significan overhead.
Solution
Implement a script that loops over SQL Monitor views and capture any SQL that took or is taking more than a few seconds. Then review these reports searching by sql_text.
Steps
1. Open a new session and execute mon_repository.sql followed by mon_capture.sql. The latter will loop indefinitely.
2. On a second session execute mon_reports.sql every so often.
3. Review table v_sql_monitor by sql_text then read corresponding report on zip.
Scripts
mon_repository.sql
REM $Header: mon_repository.sql 11.4.5.7.1 2013/04/24 carlos.sierra $ DROP TABLE v_sql_monitor; CREATE TABLE v_sql_monitor ( sql_id VARCHAR2(13), key NUMBER, sql_exec_start DATE, sql_exec_id NUMBER, status VARCHAR2(19), first_refresh_time DATE, last_refresh_time DATE, username VARCHAR2(30), capture_date DATE, report_date DATE, sql_text VARCHAR2(2000), mon_report CLOB, PRIMARY KEY (sql_id, key));
mon_capture.sql
REM $Header: mon_capture.sql 11.4.5.7.1 2013/04/24 carlos.sierra $ DECLARE l_mon_report CLOB; BEGIN LOOP INSERT INTO v_sql_monitor (sql_id, key, sql_exec_start, sql_exec_id, status, first_refresh_time, last_refresh_time, sql_text, username ) SELECT v.sql_id, v.key, v.sql_exec_start, v.sql_exec_id, v.status, v.first_refresh_time, v.last_refresh_time, v.sql_text, v.username FROM v$sql_monitor v WHERE v.process_name = 'ora' AND v.sql_text IS NOT NULL AND UPPER(v.sql_text) NOT LIKE 'BEGIN%' AND UPPER(v.sql_text) NOT LIKE 'DECLARE%' AND (v.status LIKE 'DONE%' OR (v.status = 'EXECUTING' AND (v.last_refresh_time - v.first_refresh_time) > 1/24/60 /* 1 min */)) AND NOT EXISTS (SELECT NULL FROM v_sql_monitor t WHERE t.sql_id = v.sql_id AND t.key = v.key); FOR i IN (SELECT t.*, t.ROWID row_id FROM v_sql_monitor t WHERE t.capture_date IS NULL) LOOP l_mon_report := DBMS_SQLTUNE.REPORT_SQL_MONITOR ( sql_id => i.sql_id, sql_exec_start => i.sql_exec_start, sql_exec_id => i.sql_exec_id, report_level => 'ALL', type => 'ACTIVE' ); UPDATE v_sql_monitor SET mon_report = l_mon_report, capture_date = SYSDATE WHERE ROWID = i.row_id; END LOOP; COMMIT; DBMS_LOCK.SLEEP(60); -- sleep 1 min END LOOP; END; /
mon_reports.sql
REM $Header: mon_reports.sql 11.4.5.7.1 2013/04/24 carlos.sierra $ SET ECHO OFF FEED OFF VER OFF SHOW OFF HEA OFF LIN 2000 NUM 20 NEWP NONE PAGES 0 LONG 2000000 LONGC 2000 SQLC MIX TAB ON TRIMS ON TI OFF TIMI OFF ARRAY 100 NUMF "" SQLP SQL> SUF sql BLO . RECSEP OFF APPI OFF AUTOT OFF SERVEROUT ON SIZE UNL; SPO reports_driver.sql; PRO SET ECHO OFF FEED OFF VER OFF SHOW OFF HEA OFF LIN 2000 NUM 20 NEWP NONE PAGES 0 LONG 2000000 LONGC 2000 SQLC MIX TAB ON TRIMS ON TI OFF TIMI OFF ARRAY 100 NUMF "" SQLP SQL> SUF sql BLO . RECSEP OFF APPI OFF AUTOT OFF SERVEROUT ON SIZE UNL;; BEGIN FOR i IN (SELECT t.sql_id, t.key, t.ROWID row_id FROM v_sql_monitor t WHERE t.report_date IS NULL) LOOP DBMS_OUTPUT.PUT_LINE('SPO sql_id_'||i.sql_id||'_key_'||i.key||'.html;'); DBMS_OUTPUT.PUT_LINE('SELECT mon_report FROM v_sql_monitor WHERE sql_id = '''||i.sql_id||''' AND key = '||i.key||';'); DBMS_OUTPUT.PUT_LINE('SPO OFF;'); DBMS_OUTPUT.PUT_LINE('UPDATE v_sql_monitor SET report_date = SYSDATE WHERE ROWID = '''||i.row_id||''';'); DBMS_OUTPUT.PUT_LINE('HOS zip -m mon_reports sql_id_'||i.sql_id||'_key_'||i.key||'.html'); END LOOP; END; / PRO COMMIT;; PRO SET TERM ON ECHO OFF FEED 6 VER ON SHOW OFF HEA ON LIN 80 NUM 10 NEWP 1 PAGES 14 LONG 80 LONGC 80 SQLC MIX TAB ON TRIMS OFF TI OFF TIMI OFF ARRAY 15 NUMF "" SQLP SQL> SUF sql BLO . RECSEP WR APPI OFF SERVEROUT OFF AUTOT OFF;; SPO OFF; @reports_driver.sql HOS zip -m mon_reports reports_driver.sql HOS unzip -l mon_reports SET TERM ON ECHO OFF FEED 6 VER ON SHOW OFF HEA ON LIN 80 NUM 10 NEWP 1 PAGES 14 LONG 80 LONGC 80 SQLC MIX TAB ON TRIMS OFF TI OFF TIMI OFF ARRAY 15 NUMF "" SQLP SQL> SUF sql BLO . RECSEP WR APPI OFF SERVEROUT OFF AUTOT OFF;
Good Idea Carlos !
I think the “few seconds” you are talking about are the ones that could be controlled by the “_sqlmon_threshold” parameter (5 seconds as a default)
Bertrand
bdrouvot
April 24, 2013 at 8:23 am
Bertrand,
The default of 5 seconds is fine for this case. The scripts are basically to capture the SQL Monitor report before it ages out. But thanks for reminding me of this parameter, so we can adjust it if needed.
Cheers — Carlos
Carlos Sierra
April 24, 2013 at 8:33 am
What about people who don’t have SQL tuning pack?
guest
April 25, 2013 at 2:24 pm
then they cannot use these scripts… good point!
Carlos Sierra
April 25, 2013 at 2:31 pm
What does “read corresponding report on zip” mean?
zach friese
May 1, 2013 at 12:19 pm
The monitor report script generates an HTML file for each of the SQL statements that were selected. Once you know which SQL is of your interest, you can review its generated SQL Monitor report.
Carlos Sierra
May 1, 2013 at 1:06 pm
Hi Carlos. This is a great utility. Unfortunately most of our environments are on 10g. Do you perhaps have a similar utility for Oracle 10gR2?
Thanking you in anticipation
Ravin Maharaj
May 7, 2013 at 7:45 am
No I don’t, but I may get to build one for 10g.
Carlos Sierra
May 8, 2013 at 7:30 am
Hi Carlos,
Can you please tell if you were able to build one for 10g, it would certainly helpful to me. Thanks!
kunwar
August 16, 2013 at 2:20 am
Kunwar,
Never got to it. You know, projects on top of projects…
Cheers — Carlos
Carlos Sierra
August 16, 2013 at 9:09 am