Identifying sporadic performance issues caused by outlier SQL statements is critical yet challenging in database performance monitoring. Traditional tools often rely on periodic snapshot and aggregated metrics, which mask transient spikes and outliers. This article presents a technique to deduce the individual runtime of specific SQL statement using ASH raw data. It also demonstrates two practical use cases. The discussion is divided into three parts:

1. Deducing individual runtime of specific SQL statements using ASH
2. Identifying culprit SQL for transient slowdowns.
3. Finding outlier executions for a specific SQL

Deducing Individual Runtime of SQL Statements

The method to calculate the runtime of a specific SQL statement using ASH is straightforward: subtract the SQL execution start time (sql_exec_start) from the maximum sample time (sample_time) for a given execution. This approach leverages ASH’s granular sampling—every second in v$active_session_history and every 10 seconds in dba_hist_active_sess_history— to give a approximation of the wall-clock execution time.

Using v$active_session_history The following query timelines a specific foreground session using v$active_session_history to track SQL execution:

set pagesize 100
SELECT sample_id,
       sql_id,
       sql_exec_id,
       TO_CHAR(sql_exec_start, 'HH24:MI:SS') AS sql_start_time,
       TO_CHAR(sample_time, 'HH24:MI:SS.FF3') AS sample_time
FROM v$active_session_history
WHERE session_id = 20 
  AND session_serial# = 5847
ORDER BY sample_id;

The output below shows selected samples:

   SAMPLE_ID           SQL_ID    SQL_EXEC_ID    SQL_START_TIME     SAMPLE_TIME
____________ ________________ ______________ _________________ _______________
    11842010 71u8n8xm7yqd2          16777216 11:43:24          11:43:25.973
    11842011 71u8n8xm7yqd2          16777216 11:43:24          11:43:26.973
    11842012 71u8n8xm7yqd2          16777216 11:43:24          11:43:27.974
    11842013 bfu1cbw12pp81          16777216 11:43:27          11:43:28.974
    11842014 bfu1cbw12pp81          16777216 11:43:27          11:43:29.974
...(intermediate 32 samples omitted for brevity, showing continuous execution of sql_id 'bfu1cbw12pp81') ...
    11842047 bfu1cbw12pp81          16777216 11:43:27          11:44:02.983
    11842048 bfu1cbw12pp81          16777216 11:43:27          11:44:03.983
    11842049 far4g2mw1k3q3          16777216 11:44:03          11:44:04.983
    11842050 far4g2mw1k3q3          16777216 11:44:03          11:44:05.984
    11842051 far4g2mw1k3q3          16777216 11:44:03          11:44:06.984
    11842052 far4g2mw1k3q3          16777216 11:44:03          11:44:07.984
    11842053 far4g2mw1k3q3          16777216 11:44:03          11:44:08.985
    11842054 1cyn7346wcdw5          16777216 11:44:08          11:44:09.985
 ... 

Based on the provided output, the following runtime calculations can be made:

• For the SQL ID 71u8n8xm7yqd2, the start time is 11:43:24, the last sample time is 11:43:27.974, the deduced runtime is 3.974 seconds.
• For the SQL ID bfu1cbw12pp81, the start time is 11:43:27, the last sample time is 11:44:03.983, the deduced runtime is 36.983 seconds.
• For the SQL ID far4g2mw1k3q3, the start time is 11:44:03, the last sample time is 11:44:08.985, the deduced runtime is 5.985 seconds.
• For the SQL ID 1cyn7346wcdw5, as the max sample_time is unknown, the deduced runtime cannot be calculated.

Using dba_hist_active_sess_history

The analyzed table can be changed from v$active_session_history to dba_hist_active_sess_history. The corresponding SQL query is as follows:

set pagesize 100
SELECT sample_id,
       sql_id,
       sql_exec_id,
       TO_CHAR(sql_exec_start, 'HH24:MI:SS') AS sql_start_time,
       TO_CHAR(sample_time, 'HH24:MI:SS.FF3') AS sample_time
FROM dba_hist_active_sess_history
WHERE session_id = 20 
  AND session_serial# = 5847
ORDER BY sample_id;

The output is :

Runtime calculations from this output:

• For the SQL ID bfu1cbw12pp81, the start time is 11:43:27, the last sample time is 11:43:59.982, the deduced runtime is 32.982 seconds— slightly shorter than from v$active_session_history due to the coarser sampling.
• For the SQL ID 1cyn7346wcdw5, as the max sample_time is unknown, the deduced runtime cannot be calculated.
• The 10-second interval of dba_hist_active_sess_history misses short executions, explaining why 71u8n8xm7yqd2 and far4g2mw1k3q3 don’t appear.

Analyzing the prior two outputs yields the following observation:

• Actually, SQL ends running between the maximum sample time and the next sample time, so the actual execution is slightly longer than the execution time we deduced.
• The sql_exec_start column, a DATE type, records time only to the second without sub-second precision, while the sample_time column, a TIMESTAMP(3) type, captures time with millisecond precision. This discrepancy means runtime calculations are not very precise.
• For parallel SQLs, the deduced runtime reflects the wall-clock time from the earliest sql_exec_start to the latest sample_time across all sessions involved in the execution (coordinator and slaves). Using only one session’s data underestimates the total execution time.
• Short-lived SQL statements might slip through the net if they start and finish between sampling points. However, if they are executed frequently enough, they will eventually be captured.
• v$active_session_history is more suitable for recent and active session analysis due to its higher sampling frequency (every second) and in-memory storage. This allows for more precise measurement of SQL execution times, especially for short-lived SQL statements.
• dba_hist_active_sess_history is better suited for long-term historical analysis due to its lower sampling frequency (every 10 seconds) and disk storage, providing longer data retention. However, it may miss shorter SQL executions and provides less precise time.

By understanding these differences, we can choose the appropriate view based on the specific requirements of our performance analysis or monitoring needs.