ORA-01555 encountered with huge elapsed time discrepancies in alert and awr

We encountered the well-known ORA-1555 error recently :

Fri Jun 23 21:07:02 2017
ORA-01555 caused by SQL statement below (SQL ID: a520vskru5tmy, Query Duration=3304 sec, SCN: 0x010a.b517cc1a):
SELECT BOND_REPO_DEAL_F.BOND_REPO_DEAL_ID ...

Query Duration is 3304 seconds, wow!

But when I checked the AWR report, it states the Elapsed time for the SQL is only 19.29 seconds.awr_snapshot

 

In addition, there is little information recorded in v$active_session_history. This huge discrepancy has been irritating for a long time and finally I can find the answers after bearing this question day and night.

As a matter of fact, this behavior is perfectly NORMAL. The conflict information is due to our misconceptions about SQL execution. Here is my test case.

create table caoff.T1 nologging as select * from SOR.EV_CLTRL_DTLS where rownum<10000000;

select bytes/1024/1024
from dba_segments
where segment_name='T1';

BYTES/1024/1024
---------------
           2125     <<<<<< Create one big table for select

Execute one simple query in one session, which may last several minutes:

select * from CAOFF.T1;

select sql_id
from v$sql 
where sql_fulltext like 'select * from CAOFF.%';

b6k2d3r2nkr15    <<<<<< Get the SQLID

During the execution of last SQL, we open another connection to database and issue the following query:

alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';
select FETCHES, EXECUTIONS, END_OF_FETCH_COUNT, FIRST_LOAD_TIME, ROWS_PROCESSED, ELAPSED_TIME, LAST_LOAD_TIME, LAST_ACTIVE_TIME
from v$sql
where sql_id='b6k2d3r2nkr15';

FETCHES    EXECUTIONS END_OF_FETCH_COUNT FIRST_LOAD_TIME           ROWS_PROCESSED ELAPSED_TIME LAST_LOAD_TIME            LAST_ACTIVE_TIME
---------- ---------- ------------------ ------------------------- -------------- ------------ ------------------------- -------------------
     4228          1                  0  2017-10-16/15:10:18                63406       276332 2017-10-16/15:10:18       2017-10-16 15:18:36

  FETCHES  EXECUTIONS END_OF_FETCH_COUNT FIRST_LOAD_TIME           ROWS_PROCESSED ELAPSED_TIME LAST_LOAD_TIME            LAST_ACTIVE_TIME
---------- ---------- ------------------ ------------------------- -------------- ------------ ------------------------- -------------------
     17543          1                  0 2017-10-16/15:10:18               263131       884345 2017-10-16/15:10:18       2017-10-16 15:48:07

set lines 300 pages 300 long 999999
col event for a35
col max(sample_time) for a30
col min(sample_time) for a30
select event, count(*), max(sample_time), min(sample_time)
from v$active_session_history
where sql_id = 'b6k2d3r2nkr15'
group by event
order by count(*);

EVENT                                 COUNT(*) MAX(SAMPLE_TIME)               MIN(SAMPLE_TIME)
----------------------------------- ---------- ------------------------------ ------------------------------
                                             1 16-OCT-17 03.38.01.033 PM      16-OCT-17 03.38.01.033 PM

As you can see, very little information was recorded in v$active_session_history but the query has been ACTIVE for about 38 minutes.

It is well known that FETCH is an important stage for SELECT statement. The explanation for ELAPSED_TIME column in v$sql is as follows:

Elapsed time (in microseconds) used by this cursor for parsing, executing, and fetching

It seems that the word “fetching” does NOT mean returning all the result set to client process. The reason is pretty clear. The result is out there. But when to retrieve them and how (one row a time or all at once) are totally up to the application. It would be very hard to include the whole fetching stage in ELAPSED_TIME.

Nevertheless, the LAST_ACTIVE_TIME gives us a clue about the true active period of the statement. Note the difference outputs between consecutive outputs of v$sql. The wall clock time may have elapsed for several minutes while there is minimal increase in ELAPSED_TIME.

It’s always easy to raise a question. Why this? Why that? The hard part is the journey to the answers. Most of the time, questions are useless because they cannot resolve problems. Only answers matter.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s