March 9, 2010
A question recently appeared on the OTN forums that stated the following:
I have a query joining 4 tables and it returns 48 million. I have used /+parallel(tablename,4) */ hint with the select clause. I want to the 48 million returned by the query to another table t2.
I do get the select result in 20 minutes. when I am performing insert, I checked gv$session_longops. I usually check like select * from gv$session_longops where time_remaining>0.
It didnt return anything. I removed the where clause and rather gave the sid.(i found the sql_id from gv$session)
select * from gv$session_longops where sql_id=’XXXXXXX’;
I got 3 rows but time_remaining column is 0. Could someone explain why this is so.
OS: Linux
DB:11.1.0.6.0 – 11g
Rac- 2 node RAC
So what is happening, why does GV$SESSION_LONGOPS show 3 rows for the SQL statement, all with the TIME_REMAINING column set to 0? This is a good question, but I do not know if there is a straight-forward answer for the question. Possibly one of the first questions to ask is: What is the SQL statement, and what does its execution plan look like?
It probably makes sense to check the documentation for the GV$SESSION_LONGOPS view (or more accurately, the documentation for the single instance V$SESSION_LONGOPS view):
“V$SESSION_LONGOPS displays the status of various operations that run for longer than 6 seconds (in absolute time). These operations currently include many backup and recovery functions, statistics gathering, and query execution, and more operations are added for every Oracle release.
To monitor query execution progress, you must be using the cost-based optimizer and you must:
- Set the TIMED_STATISTICS or SQL_TRACE parameters to true
- Gather statistics for your objects with the ANALYZE statement or the DBMS_STATS package”
From the above, having the TIMED_STATISTICS parameter set to FALSE or failing to gather the statistics for the objects using DBMS_STATS are two possible reasons for the TIME_REMAINING column being set to 0. Any other ideas? Where is that SQL statement and execution plan when you need it? Why ask for the execution plan? From the documentation link you will notice that the view definition includes the SQL_PLAN_LINE_ID column, which refers to a specific line in the execution plan for the query. From this bit of information, we just need to define what is considered an operation (and does it have to be an uninterrupted operation) – without parallel query we might be able to perform a couple of tests. The definition of an operation and the 6 second rule might be very important.
We will use tables T3 and T4 from yesterday’s blog article since the original poster did not provide a SQL statement to reproduce the problem. Consider the following query:
SELECT
T3.C1,
T3.C2,
T4.C3
FROM
T3,
T4
WHERE
TRUNC(T3.C2) BETWEEN TO_DATE('08-MAR-2009','DD-MON-YYYY')
AND TO_DATE('01-JUL-2009','DD-MON-YYYY')
AND T3.C2=T4.C2;
If we set the STATISTICS_LEVEL parameter to ALL at the session level, run the SQL statement, and then generate the DBMS_XPLAN for the last execution, we may see an execution plan that looks something like this:
SQL_ID 2d4f5x92axqgn, child number 0
-------------------------------------
SELECT T3.C1, T3.C2, T4.C3 FROM T3, T4 WHERE
TRUNC(T3.C2) BETWEEN TO_DATE('08-MAR-2009','DD-MON-YYYY') AND
TO_DATE('01-JUL-2009','DD-MON-YYYY') AND T3.C2=T4.C2
Plan hash value: 1396201636
-------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 874K|00:03:31.20 | 3771K| 3763K| | | |
|* 1 | HASH JOIN | | 1 | 849K| 874K|00:03:31.20 | 3771K| 3763K| 33M| 5591K| 50M (0)|
|* 2 | TABLE ACCESS FULL| T3 | 1 | 802K| 795K|00:02:32.69 | 2743K| 2743K| | | |
| 3 | TABLE ACCESS FULL| T4 | 1 | 25M| 25M|00:00:35.93 | 1028K| 1020K| | | |
-------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("T3"."C2"="T4"."C2")
2 - filter((TRUNC(INTERNAL_FUNCTION("C2"))>=TO_DATE(' 2009-03-08 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
TRUNC(INTERNAL_FUNCTION("C2"))<=TO_DATE(' 2009-07-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))
From the above, we are able to see that Oracle is reporting that the full table scan of table T3 required roughly 152.69 seconds and the full table scan of table T4 required roughly 35.93 seconds. Assume that in another session we executed the following SQL statement roughly every 6 seconds while the above SQL statement was in the process of being executed:
SELECT SQL_ID, SQL_PLAN_HASH_VALUE HASH_VALUE, SQL_PLAN_LINE_ID LINE_ID, OPNAME, TARGET, TARGET_DESC, TIME_REMAINING, ELAPSED_SECONDS, SID, SERIAL#, USERNAME FROM V$SESSION_LONGOPS WHERE TIME_REMAINING>0;
The output of the above SQL statement might look something like the following:
SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- --------------- --------------- ------------ -------------- --------------- ---------- ---------- -------- 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 104 53 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 92 62 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 82 73 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 74 81 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 59 95 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 52 101 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 41 112 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 33 120 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 23 131 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 14 140 159 909 TESTUSER 2d4f5x92axqgn 1396201636 2 Table Scan TESTUSER.T3 5 148 159 909 TESTUSER no rows selected 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 57 10 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 42 18 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 27 31 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 18 41 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 53 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 57 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 63 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 70 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 75 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 81 159 909 TESTUSER 2d4f5x92axqgn 1396201636 3 Table Scan TESTUSER.T4 6 86 159 909 TESTUSER no rows selected
From the above output it appears that the full table scan of table T3 required between 148 and 154 seconds. At the point where the full table scan of T3 completed and the first couple of seconds (probably 6) of the full table scan of T4, the SQL statement executed in the second session returned no rows – after roughly 6 seconds of reading table T4, the query of V$SESSION_LONGOPS started reporting that table T4 was being read. From the above it appears that the read of table T4 required between 86 and 94 seconds, yet that does not agree with the DBMS_XPLAN output – it appears that in the V$SESSION_LONGOPS output the hash join operation’s time is being reported as part of this elapsed time for reading table T4.
So, we have found a third possible reason for the rows in V$SESSION_LONGOPS appearing as 0 for the OP’s SQL statement – the line in the plan had not yet consumed 6 seconds of time, or the operation had already completed.
Let’s look at one of the other SQL statements from yesterday’s blog article:
SELECT
T3.C1,
T3.C2,
T4.C3
FROM
T3,
T4
WHERE
T3.C2 BETWEEN TO_DATE('08-MAR-2009','DD-MON-YYYY')
AND TO_DATE('01-JUL-2009','DD-MON-YYYY') + (1-1/24/60/60)
AND T3.C2=T4.C2;
This statement is equivalent to the previous SQL statement, except that it is able to use the index that exists on table T3. The execution plan follows:
SQL_ID 539d93k50ruz3, child number 0
-------------------------------------
SELECT T3.C1, T3.C2, T4.C3 FROM T3, T4 WHERE T3.C2
BETWEEN TO_DATE('08-MAR-2009','DD-MON-YYYY') AND
TO_DATE('01-JUL-2009','DD-MON-YYYY') + (1-1/24/60/60) AND T3.C2=T4.C2
Plan hash value: 1243183227
--------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 874K|00:00:05.19 | 85051 | | | |
| 1 | MERGE JOIN | | 1 | 795K| 874K|00:00:05.19 | 85051 | | | |
| 2 | TABLE ACCESS BY INDEX ROWID | T4 | 1 | 795K| 795K|00:00:01.69 | 51097 | | | |
|* 3 | INDEX RANGE SCAN | IND_T4_C2 | 1 | 795K| 795K|00:00:00.42 | 10841 | | | |
|* 4 | SORT JOIN | | 795K| 795K| 874K|00:00:02.11 | 33954 | 30M| 1977K| 26M (0)|
| 5 | TABLE ACCESS BY INDEX ROWID| T3 | 1 | 795K| 795K|00:00:00.58 | 33954 | | | |
|* 6 | INDEX RANGE SCAN | IND_T3_C2 | 1 | 795K| 795K|00:00:00.18 | 2114 | | | |
--------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("T4"."C2">=TO_DATE(' 2009-03-08 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND "T4"."C2"<=TO_DATE(' 2009-07-01
23:59:59', 'syyyy-mm-dd hh24:mi:ss'))
4 - access("T3"."C2"="T4"."C2")
filter("T3"."C2"="T4"."C2")
6 - access("T3"."C2">=TO_DATE(' 2009-03-08 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND "T3"."C2"<=TO_DATE(' 2009-07-01
23:59:59', 'syyyy-mm-dd hh24:mi:ss'))
The above SQL statement completed too quickly to report any time in the V$SESSION_LONGOPS view, so let’s set the ’08-MAR-2009′ date to ’08-MAR-2007′ and re-run the SQL statement. For quite a bit of time the query of V$SESSION_LONGOPS only returned the following:
no rows selected
But the SQL statement was executing, why did it not appear in V$SESSION_LONGOPS – where is that link for reporting a bug on Metalink? 🙂 Or maybe, just maybe, Oracle is not performing any single operation in the execution plan continuously for more than 6 seconds (reading the index at ID 3 followed by the corresponding rows at ID 2, and then back to the index at ID 3 again).
Eventually, the following appeared after what must have been a minute or two:
SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- --------------- --------------- ------------ -------------- --------------- ---------- ---------- -------- f3scvt222bu0t 1243183227 4 Sort Output 1194 12 159 909 TESTUSER f3scvt222bu0t 1243183227 4 Sort Output 2115 22 159 909 TESTUSER f3scvt222bu0t 1243183227 4 Sort Output 2115 22 159 909 TESTUSER ... (in the above the last row continued to repeat with ELAPSED_SECONDS displayed as 22 for a minute or two)
Ready, aim,… hey – what is the TARGET. The LINE_ID column (the SQL_PLAN_LINE_ID column in V$SESSION_LONGOPS) reported that Oracle is executing ID 4 of the execution plan. I can’t explain why the last line remained in the V$SESSION_LONGOPS output for a minute or two (maybe someone else knows why).
So, we have found a fourth possible reason for the rows in V$SESSION_LONGOPS appearing as 0 for the OP’s SQL statement – it could be that Oracle was alternating between an index range scan and the retrieval of the matching rows from the corresponding table.
Let’s try executing the first query with a parallel hint to see what happens to the V$SESSION_LONGOPS output:
SELECT /*+ PARALLEL (T3, 4) PARALLEL (T4, 4) */
T3.C1,
T3.C2,
T4.C3
FROM
T3,
T4
WHERE
TRUNC(T3.C2) BETWEEN TO_DATE('08-MAR-2009','DD-MON-YYYY')
AND TO_DATE('01-JUL-2009','DD-MON-YYYY')
AND T3.C2=T4.C2;
The DBMS_XPLAN output for the query follows:
SQL_ID dywt9v0xuvgyv, child number 0
-------------------------------------
SELECT /*+ PARALLEL (T3, 4) PARALLEL (T4, 4) */ T3.C1, T3.C2,
T4.C3 FROM T3, T4 WHERE TRUNC(T3.C2) BETWEEN
TO_DATE('08-MAR-2009','DD-MON-YYYY') AND
TO_DATE('01-JUL-2009','DD-MON-YYYY') AND T3.C2=T4.C2
Plan hash value: 1800244878
-------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 874K|00:03:49.60 | 14 | | | |
| 1 | PX COORDINATOR | | 1 | | 874K|00:03:49.60 | 14 | | | |
| 2 | PX SEND QC (RANDOM) | :TQ10001 | 0 | 849K| 0 |00:00:00.01 | 0 | | | |
|* 3 | HASH JOIN | | 0 | 849K| 0 |00:00:00.01 | 0 | 126M| 10M| 49M (0)|
| 4 | PX RECEIVE | | 0 | 802K| 0 |00:00:00.01 | 0 | | | |
| 5 | PX SEND BROADCAST | :TQ10000 | 0 | 802K| 0 |00:00:00.01 | 0 | | | |
| 6 | PX BLOCK ITERATOR | | 0 | 802K| 0 |00:00:00.01 | 0 | | | |
|* 7 | TABLE ACCESS FULL| T3 | 0 | 802K| 0 |00:00:00.01 | 0 | | | |
| 8 | PX BLOCK ITERATOR | | 0 | 25M| 0 |00:00:00.01 | 0 | | | |
|* 9 | TABLE ACCESS FULL | T4 | 0 | 25M| 0 |00:00:00.01 | 0 | | | |
-------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("T3"."C2"="T4"."C2")
7 - access(:Z>=:Z AND :Z<=:Z)
filter((TRUNC(INTERNAL_FUNCTION("C2"))>=TO_DATE(' 2009-03-08 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
TRUNC(INTERNAL_FUNCTION("C2"))<=TO_DATE(' 2009-07-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))
9 - access(:Z>=:Z AND :Z<=:Z)
filter(SYS_OP_BLOOM_FILTER(:BF0000,"T4"."C2"))
A bloom filter, just in time for Spring (it must be true, it is in the Predicate Information section of the actual execution plan).
After roughly a 6 second delay, V$SESSION_LONGOPS was queried roughly every 6 seconds. The output of the V$SESSION_LONGOPS query follows:
SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 8 7 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 4 7 80 544 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 114 7 7 251 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 14 7 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 2 16 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 4 9 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 1 13 80 544 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 7 251 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 13 9 80 544 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 2 12 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 10 7 251 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 6 7 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 7 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 4 10 80 544 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 2 13 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 4 9 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 6 10 7 251 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 10 8 80 544 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 2 12 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 1 16 80 544 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 3 10 7 251 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 6 10 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 6 8 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 8 8 80 544 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 3 12 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 4 10 553 243 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 5 10 80 544 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 5 8 7 251 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 7 9 159 982 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 2 57 80 544 TESTUSER dywt9v0xuvgyv 1800244878 7 Rowid Range Scan TESTUSER.T3 20 66 159 982 TESTUSER SQL> / no rows selected SQL> / no rows selected SQL> / no rows selected SQL> / no rows selected SQL> / no rows selected SQL> / no rows selected SQL> / no rows selected SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 9 8 81 1204 TESTUSER dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 4 7 395 631 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 69 13 160 32 TESTUSER dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 12 16 81 1204 TESTUSER dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 5 15 395 631 TESTUSER dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 71 13 238 31 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 11 25 81 1204 TESTUSER dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 4 24 395 631 TESTUSER dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 58 22 238 31 TESTUSER SQL> / SQL_ID HASH_VALUE LINE_ID OPNAME TARGET TARGET_DESC TIME_REMAINING ELAPSED_SECONDS SID SERIAL# USERNAME ------------- ---------- ---------- ---------------- --------------- ----------- -------------- --------------- ---------- ---------- -------- dywt9v0xuvgyv 1800244878 9 Rowid Range Scan TESTUSER.T4 7 33 81 1204 TESTUSER SQL> / no rows selected
As you can see from the above, the parallel query processes (each with a different SID) appear, and disappear from the V$SESSION_LONGOPS output as the query executes. The output shows a roughly 40 to 50 second time period during the execution of the query in the first session where nothing appeared in the V$SESSION_LONGOPS output.
So, we have found a fifth possible reason for the rows in V$SESSION_LONGOPS appearing as 0 for the OP’s SQL statement – the OP may have just queried V$SESSION_LONGOPS at the wrong time.
Any other possible reasons why the OP would see 0 for the TIME_REMAINING column when querying V$SESSION_LONGOPS during the execution of a SQL statement that is expected to require 20 minutes to complete?
Charles Hooper's Oracle Notes 
Since OP is on 11g, it’s probably better idea to utilize SQL monitor for that purpose. Unfortunately, it’s not free: Diagnostic+Performance Packs licenses are required.
Timur,
Good idea – I did not think to suggest using SQL Plan Monitoring. I think that it is also important that you mentioned that using SQL Plan Monitoring requires additional cost licenses – it seems that all too often people recommend that other people use feature X to solve problem Y without mentioning that the first problem to solve involves $/£/€/(your currency symbol here) to buy the extra cost Oracle feature that is being recommended.
I wonder how much information SQL Plan Monitoring would provide for the above sample SQL statements?
> I wonder how much information SQL Plan Monitoring would provide for the above sample SQL statements?
In short – it is enough to understand at which exactly execution plan step response time is lost. In fact SQL monitoring is the most appropriate tool for PX. Refert to Greg Rahn’s post on this topic for example.
I am a big fan of LongOps.
I created two utilities to watch the progress of LongOps. In the past I used them a lot to monitor export progress, index rebuilds, or long updates during database upgrades.
1) Perl: With 10g the Perl installation has DBI already installed so this is pretty easy to configure Perl script that talk to the DB via DBI. I have a text mode Perl script to watch LongOps here: http://ba6.us/node/102
2) SQL Developer: I created a prettified SQL Developer report here: http://ba6.us/node/115 . The benefit of SQL Developer is it is easy to configure. Also you can set the reports to repeat at intervals (that is if they fixed their leaking cursor issue).
[…] 15-Why does my sql not show up in v$session_longops -possible reasons for time_remaining=0 (how does v$session_longops work) ? Charles Hooper-V$SESSION_LONGOPS – Where’s My SQL Statement […]