Dion Cho – Oracle Performance Storyteller

We are natural born scientists

How long is my query being executed?

with 7 comments

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!

About these ads

Written by Dion Cho

May 2, 2009 at 8:48 am

Posted in Misc.

Tagged with , ,

7 Responses

Subscribe to comments with RSS.

  1. Dion, v$transaction.start_time may not show when the last dml statement started, it shows the start time of the transaction, the transaction may have been started with a different dml.

    Yas

    May 4, 2009 at 1:43 pm

  2. Would’nt the v$session_longops serve the purpose to track elapsed time of long running queries?

    abcd

    September 2, 2009 at 8:52 pm

    • ABCD. :)

      V$SESSION_LONGOPS view has some restrictions as explained here.
      http://www.gplivna.eu/papers/v$session_longops.htm

      But still, it’s a nice try to examine V$SESSION_LONGOPS view.

      Dion Cho

      September 3, 2009 at 1:53 am

    • Hello,

      I’ve got a CREATE INDEX statement that takes several minutes, but the task isn’t reported by v$session_longops. Is is possible to make ORACLE display a db operation in that view?

      Tim

      September 10, 2009 at 8:04 am

      • Tim.

        CREATE INDEX would do table full scan or index fast full scan, which would be reported via V$SESSION_LONGOPS view. Yes, index creation itself is not appear but all you get would be table full scan/index fast full scan operation.

        But I have no idea why your long-running index creation session does not appear on that view. Do you have any unusual things with your job?

        Regards.

        Dion Cho

        September 10, 2009 at 8:42 am

      • I use the ORACLE TEXT feature in order to index and search pdf documents. The CREATE INDEX statement is:
        ‘CREATE INDEX text_index ON pdfs(pdf) INDEXTYPE IS CTXSYS.CONTEXT’ – but there doesn’t appear any entry in V$SESSION_LONGOPS.

        Tim

        September 10, 2009 at 8:52 am

        • More research clearly showed that even index creation on text should appear in the V$SESSION_LONGOPS view while it is reading data with full table scan.

          One thing you should investigate is the size of the table. For full table scan, Oracle registeres it to the V$SESSION_LONGOPS view only when the table size over 10,000 block.

          Dion Cho

          September 11, 2009 at 1:05 am


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

Follow

Get every new post delivered to your Inbox.

Join 58 other followers

%d bloggers like this: