How long is my query being executed?

The one of the basic questions in performance montoring is as following.

How long is my query being executed?

The funny thing is that it’s really hard to answer this question.

In case of DML statement(update/delete/insert), we can query v$transaction.start_time column.

In case of SELECT statement, V$SESSION.LAST_CALL_ET seems to be the answer. But unfortunately, V$SESSION.LAST_CALL_ET is reset with the change of the status of the session. See following.

1. Start long-running query in session #1(147)

UKJA@ukja102> @mysid

       SID
----------
       147

UKJA@ukja102> select level from dual connect by level <= 10000000;
1
2
3
...

2. Check the value of v$session.last_call_et in session #2

UKJA@ukja102> select sql_id, status, last_call_et from v$session where sid = 147;

-- Unfortunately, the last_call_et continues to reset with the status being changed
UKJA@ukja102> /

SQL_ID        STATUS   LAST_CALL_ET
------------- -------- ------------
0tpw3hbmz4pvw INACTIVE            0

UKJA@ukja102> /

SQL_ID        STATUS   LAST_CALL_ET
------------- -------- ------------
0tpw3hbmz4pvw ACTIVE              0

UKJA@ukja102> /

SQL_ID        STATUS   LAST_CALL_ET
------------- -------- ------------
0tpw3hbmz4pvw INACTIVE            0

Why we have the continuous change of the session status? Once Oracle retrieves the rows in ACTIVE status, it sends the result to the client and waits for the additional request from client with the wait event of “SQL*Net message from client”.

Because it is just waiting, the status is now INACTIVE, and the LAST_CALL_ET is reset.

This is the problem, isn’t it? We can’t never get the real elapsed time of the current query from the dynamic performance views.

For this reason, Oracle 11g introduced V$SESSION.SQL_EXEC_START column.

SQL_ID                     STATUS           LAST_CALL_ET (SYSDATE-SQL_EXEC_START)*86400
-------------------------- ---------------- ------------ ------------------------------
0tpw3hbmz4pvw              INACTIVE                    0                            162

SQL> /

SQL_ID                     STATUS           LAST_CALL_ET (SYSDATE-SQL_EXEC_START)*86400
-------------------------- ---------------- ------------ ------------------------------
0tpw3hbmz4pvw              ACTIVE                      0                            162

SQL> /

SQL_ID                     STATUS           LAST_CALL_ET (SYSDATE-SQL_EXEC_START)*86400
-------------------------- ---------------- ------------ ------------------------------
0tpw3hbmz4pvw              INACTIVE                    0                            163

Okidoki!