What do you do when you’re dealing with an ongoing performance issue and somebody’s watching over your shoulder and asking something like “Hey, has our commits’ response time become any better by now?”. Or, if you’re observing a spike in IO requests that doesn’t last for too long, and you want to see how much worse the response times of db file sequential read events gets? Writing queries at these moments require time which one doesn’t have, so I’ve written a script that I already use in situations like these

As the title suggests, the script is very simple, it relies on SQL*Plus variables to preserve the retrieved values and uses them to calculate deltas when the query is executed again.

The latest version of the script will always be here: rt_wait_perf.sql

The script contains a single SQL statement and nothing else:

set lines 300 ver off feed off
def v_tst=''
def v_wts='0'
def v_twm='0'
def v_event='&1';
col TIME_WAITED_MICRO for a15 new_value v_twm
col TOTAL_WAITS for a15 new_value v_wts
col TSTAMP for a26 new_value v_tst
col D_WTS for 9999999999999
col D_TWM for 9999999999999
col D_AVG_MS_WT for 999999999.999
col INTERVAL_SECS for 999999999.999
col EVENT for a40
select to_char(systimestamp,'DD.MM.YYYY HH24:MI:SSXFF') TSTAMP,
       round(sysdate+(86400*(systimestamp-to_timestamp('&&v_tst','DD.MM.YYYY HH24:MI:SSXFF')))-sysdate,3) interval_secs,
       event,
       to_char(TOTAL_WAITS) TOTAL_WAITS,
       to_char(TIME_WAITED_MICRO) TIME_WAITED_MICRO,
       TOTAL_WAITS-&&v_wts D_WTS,
       TIME_WAITED_MICRO-&&v_twm D_TWM,
       round((TIME_WAITED_MICRO-&&v_twm)/decode(TOTAL_WAITS-&&v_wts,0,null,TOTAL_WAITS-&&v_wts)/1000,3) D_AVG_MS_WT
from v$system_event
where event='&&v_event';

Here’s how you use it:

  1. It requires one argument - the name of the wait event that you want to monitor, i.e SQL> @rt_wait_perf.sql "log file sync"
  2. Simply execute the SQL statement again (by using /) to get the delta values and milliseconds/wait since the previous execution of the SQL
  3. Keep in mind it shows the info for the current instance only (it queries from v$system_event)
  4. Most of the times you’ll be interested in outputs for “D_WTS” and “D_AVG_MS_WT” columns to see how many times the wait occurred and how long they were during the reference interval.

This is how it works:

SQL> @rt_wait_perf "log file sync"

TSTAMP                      INTERVAL_SECS EVENT           TOTAL_WAITS     TIME_WAITED_MIC       D_WTS         D_TWM D_AVG_MS_WT
-------------------------- -------------- --------------- --------------- --------------- ----------- ------------- -----------
14.04.2016 18:07:25.055984                log file sync   137478504       1096070215896     137478504 1096070215896       7.973
SQL> /

TSTAMP                      INTERVAL_SECS EVENT           TOTAL_WAITS     TIME_WAITED_MIC       D_WTS         D_TWM D_AVG_MS_WT
-------------------------- -------------- --------------- --------------- --------------- ----------- ------------- -----------
14.04.2016 18:07:45.189085         20.133 log file sync   137478672       1096070457766           168        241870       1.440
SQL> /

TSTAMP                      INTERVAL_SECS EVENT           TOTAL_WAITS     TIME_WAITED_MIC       D_WTS         D_TWM D_AVG_MS_WT
-------------------------- -------------- --------------- --------------- --------------- ----------- ------------- -----------
14.04.2016 18:08:00.585761         15.397 log file sync   137478819       1096070666101           147        208335       1.417

Columns reference:

  • TSTAMP - current timestamp
  • INTERVAL_SECS - elapsed time in seconds since previous execution. This is the wall clock time interval between the “snapshots” used to calculate the deltas
  • EVENT - name of the wait event
  • TOTAL_WAITS - total number of waits
  • TIME_WAITED_MIC - total time spent on the wait event in microseconds
  • D_WTS - delta number of waits (since the previous execution)
  • D_TWM - delta time spent on the wait event in microseconds (since the previous execution)
  • D_AVG_MS_WT - average milliseconds per wait event (since the previous execution)

Enjoy!