Recently I came across an issue where the actual response time of a SQL statement was 50 seconds but v$sql.elapsed_time reported 2400 seconds. AWR too reported 2400 seconds. So, what was going on here ? I saw the execution plan, it was running in Parallel.
This is actually an expected behavior. When the query runs in parallel, v$sql.elapsed_time reports the total elapsed time taken by the query coordinator (QC) and all the parallel slaves. My query was running with 48 parallel slaves. This is why elapsed time in v$sql was seen ~48x higher.
Interestingly elapsed_time in v$sql_monitor displays correct response time. This view displays time associated with the query coordinator process alone.
Takeaway, do not panic if you see a high elapsed time for SQL statements in the AWR report because elapsed time is not necessarily the actual response time.
You can query ASH data to get the wall clock time of a parallel query. It also has a PX_FLAGS column which is currently undocumented but it can tell the degree of parallelism your SQL used in the past
This is actually an expected behavior. When the query runs in parallel, v$sql.elapsed_time reports the total elapsed time taken by the query coordinator (QC) and all the parallel slaves. My query was running with 48 parallel slaves. This is why elapsed time in v$sql was seen ~48x higher.
Interestingly elapsed_time in v$sql_monitor displays correct response time. This view displays time associated with the query coordinator process alone.
Takeaway, do not panic if you see a high elapsed time for SQL statements in the AWR report because elapsed time is not necessarily the actual response time.
You can query ASH data to get the wall clock time of a parallel query. It also has a PX_FLAGS column which is currently undocumented but it can tell the degree of parallelism your SQL used in the past
SELECT SQL_ID,
SQL_EXEC_START,
SQL_PLAN_HASH_VALUE PHV,
MIN (sample_time)
SQL_START_TIME,
MAX (sample_time)
SQL_END_TIME,
ROUND (
( CAST (MAX (sample_time) AS DATE)
- CAST (SQL_EXEC_START AS DATE))
* 3600
* 24)
etime_secs,
ROUND (SUM (delta_read_io_bytes) / 1024 / 1024 / 1024, 2)
PHYSICAL_READ_GB,
ROUND (SUM (delta_interconnect_io_bytes) / 1024 / 1024 / 1024, 2)
INTERCONNECT_IO_GB,
MAX (TRUNC (px_flags / 2097152))
ACTUAL_DEGREE,
MIN (NULLIF (TRUNC (px_flags / 2097152), 0))
MIN_ACTUAL_DEGREE
FROM DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sql_id = 'dthn77sj0wpdk' AND (SQL_EXEC_START IS NOT NULL OR SQL_EXEC_ID IS NOT NULL)
GROUP BY SQL_ID,
SQL_EXEC_START,
SQL_PLAN_HASH_VALUE,
SQL_EXEC_ID,
QC_INSTANCE_ID,
QC_SESSION_ID,
QC_SESSION_SERIAL#
ORDER BY SQL_EXEC_START DESC
