How long is my query being executed?

The one of the basic questions in performance montoring is as following. Most of people want to know how to find long running queries? Basically in standard editions where AWR reports are not available or point in time if you want to find long running queries, then oviously we need views to find the answer and 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. Letus find queries running more than 10 minutes

SQL> @et10_1.sql

      Inst SidS#           USERNAME             PROGRAM    SQL_ID          WAIT_CLASS STATUS     TERMINAL              wait   PORT
---------- --------------- -------------------- ---------- --------------- ---------- ---------- --------------- ---------- ------
         1 923,8517        BILLPAY       w3wp.exe   9aju2k9xz0wby   User I/O   ACTIVE     APP1          96   12049
         1 779,16113       BILLPAY       w3wp.exe   9aju2k9xz0wby   User I/O   ACTIVE     APP2          23.7   14671
         2 918,7777        BILLPAY      w3wp.exe   aap9qvd57f5d2   User I/O   ACTIVE     APP1           12.3   6854

SQL>

The above query is showing the queries running last 10 minutes or more with sqlid and other details as shown above. But you may face frequently sid changing but the sqlid may same. That means the above query is suitable to find if any query is running. ( you may change last_call_et value as per your choice)

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”.

Note : When the status is INACTIVE, then LAST_CALL_ET value will 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> @et10_2.sql

      Inst SidS#           USERNAME             PROGRAM    SQL_ID          WAIT_CLASS STATUS     TERMINAL              wait SQL_EXEC_START
---------- --------------- -------------------- ---------- --------------- ---------- ---------- --------------- ---------- ----------------------
         1 923,8517        BILLPAY       w3wp.exe   9aju2k9xz0wby   User I/O   ACTIVE     APP1         115.4 18/08/16 08:08:22
         1 2174,13449      BILLPAY       w3wp.exe   9aju2k9xz0wby   User I/O   ACTIVE     APP1              48 18/08/16 09:08:44
         1 779,16113       BILLPAY       w3wp.exe   9aju2k9xz0wby   User I/O   ACTIVE     APP1            43 18/08/16 10:08:42
         1 1600,26713      BILLPAY       w3wp.exe   9aju2k9xz0wby   User I/O   ACTIVE     APP2           29.1 18/08/16 10:08:40
         2 634,20687       BILLPAY      w3wp.exe   1vgd2v3rx4dz0   User I/O   ACTIVE     APP1             12.4 18/08/16 10:08:45
SQL>

What does the v$session column last_call_et do?

Answer:  According to Oracle, the last_call_et column of v$session  "represents the elapsed time (in seconds) since the session has become active. . . .If the session status column is currently ACTIVE, then the value of last_call_et represents the elapsed time in seconds since the session has become active.  If the session status column is currently INACTIVE, then the value of last_call_et represents the elapsed time in seconds since the session has become inactive."

 In plain English, last_call_et will tell you how long a session has been running (in wall clock seconds), but this depends on the setting for the optimizer_mode parameter (as seen in the v$sql_plan view).  If it is optimizer_mode=all_rows (the default), the last_call_et will reflect the total elapsed time, while if you are using first_rows, the last_call_et will re-set for each change in status.  Here is a query using last_call_et:

select ses.username,
       ses.machine,
       ses.program,
       ses.status,
       ses.last_call_et,
       sql.hash_value,
       sql.sql_text
  from v$session ses, v$sql sql
 where ses.sql_hash_value = sql.hash_value
   and ses.type = 'USER' order by last_call_et desc;

If you are running a DML (insert, update, delete) last_call_et tells you how long an update has been running.

Of course, a session many issue many DML and SQL statements so care must be used when interpreting the last_call_et column.

Used queries:

1) et10_1.sql

Select inst_id "Inst",SID||','||serial# "SidS#",username,PROGRAM,sql_id,wait_class,status,terminal,
round(last_call_et/60,1) "wait",port
  from gv$session
where type != 'BACKGROUND'   and status = 'ACTIVE'   and username is not null
and wait_class in ('Concurrency', 'System I/O', 'User I/O','Network','Apllication')
and round(last_call_et/60,1) > 10
order by "wait" desc;


2) et10_2.sql

Select inst_id "Inst",SID||','||serial# "SidS#",username,PROGRAM,sql_id,wait_class,status,terminal,
round(last_call_et/60,1) "wait",to_char(SQL_EXEC_START,'dd/mm/yy hh24:mm:ss') "SQL_EXEC_START"
  from gv$session
where type != 'BACKGROUND'   and status = 'ACTIVE'   and username is not null
and wait_class in ('Concurrency', 'System I/O', 'User I/O','Network','Apllication')
and round(last_call_et/60,1) > 10
order by "wait" desc;

Click here to trouble-shoot slowness issues