Oracle Database Discussions

Hi,
Are LOBs, etc. included in the table?
Are there any waits occurring?
Is it possible to upload execution plans and SQL trace information?
Regards,

There are no LOBS in the table.
The waits are as below.
event p1 p2 p3
db file sequential read 5 4149679 1

The session sql explain plan is below.
"Query Plan" "Rows"
"SELECT STATEMENT Cost = 269985" " "
"SORT AGGREGATE " " 1 "
" VIEW " " 42 "
" UNION-ALL " " "
" FILTER " " "
" HASH JOIN OUTER " " 2 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 2 "
" INLIST ITERATOR " " "
" TABLE ACCESS BY INDEX ROWID BATCHED VAC_000087FD " " 17 "
" INDEX RANGE SCAN I_220101_VAC_000087FD_1 " " 17 "
" TABLE ACCESS FULL VLD_00008866 " " 41K"
" TABLE ACCESS FULL CCH_00008868 " " 59K"
" HASH JOIN ANTI SNA " " 3 "
" FILTER " " "
" NESTED LOOPS OUTER " " 3 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 3 "
" VIEW " " 10K"
" HASH JOIN RIGHT ANTI SNA " " 10K"
" INDEX FULL SCAN SYS_C00364276 " " 1 "
" TABLE ACCESS FULL VAC_00006D1B " " 10K"
" TABLE ACCESS FULL VLD_00006D22 " " 559K"
" VIEW PUSHED PREDICATE " " 1 "
" FILTER " " "
" MERGE JOIN ANTI NA " " 70 "
" SORT JOIN " " 7K"
" TABLE ACCESS BY INDEX ROWID BATCHED CCH_00007BB0 " " 7K"
" INDEX FULL SCAN SYS_C00353046 " " 7K"
" SORT UNIQUE " " 8K"
" TABLE ACCESS FULL LNK_00008614 " " 8K"
" INDEX FAST FULL SCAN SYS_C00364277 " " 56K"
" HASH JOIN ANTI SNA " " 1 "
" FILTER " " "
" NESTED LOOPS OUTER " " 1 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 1 "
" VIEW " " 12 "
" HASH JOIN ANTI SNA " " 12 "
" TABLE ACCESS FULL VAC_00007C1D " " 12 "
" INDEX FULL SCAN SYS_C00365638 " " 1 "
" TABLE ACCESS FULL VLD_00007C24 " " 11K"
" VIEW PUSHED PREDICATE " " 1 "
" FILTER " " "
" MERGE JOIN ANTI NA " " 84 "
" SORT JOIN " " 158 "
" TABLE ACCESS BY INDEX ROWID BATCHED CCH_00007C26 " " 158 "
" INDEX FULL SCAN SYS_C00353233 " " 158 "
" SORT UNIQUE " " 74 "
" TABLE ACCESS FULL LNK_00008787 " " 74 "
" INDEX FAST FULL SCAN SYS_C00365640 " " 965 "
" HASH JOIN ANTI SNA " " 27 "
" FILTER " " "
" HASH JOIN OUTER " " 27 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 27 "
" VIEW " " 12 "
" HASH JOIN ANTI SNA " " 12 "
" INLIST ITERATOR " " "
" TABLE ACCESS BY INDEX ROWID BATCHED VAC_00006CC2 " " 12 "
" INDEX RANGE SCAN I_200101_VAC_00006CC2_1 " " 12 "
" INDEX FULL SCAN SYS_C00364113 " " 1 "
" TABLE ACCESS FULL VLD_00006CC9 " " 623K"
" VIEW " " 699K"
" HASH JOIN RIGHT ANTI NA " " 699K"
" TABLE ACCESS FULL LNK_000084B2 " " 1K"
" TABLE ACCESS FULL CCH_00007BAB " " 700K"
" INDEX FAST FULL SCAN SYS_C00364114 " " 9K"
" HASH JOIN ANTI SNA " " 5 "
" FILTER " " "
" HASH JOIN OUTER " " 5 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 5 "
" VIEW " " 9K"
" HASH JOIN RIGHT ANTI SNA " " 9K"
" INDEX FULL SCAN SYS_C00364266 " " 1 "
" TABLE ACCESS FULL VAC_00006CE2 " " 9K"
" TABLE ACCESS FULL VLD_00006CE9 " " 559K"
" VIEW " " 696K"
" HASH JOIN RIGHT ANTI NA " " 696K"
" TABLE ACCESS FULL LNK_000085F0 " " 8K"
" TABLE ACCESS FULL CCH_00007BAC " " 704K"
" INDEX FAST FULL SCAN SYS_C00364267 " " 59K"
" FILTER " " "
" HASH JOIN OUTER " " 1 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 1 "
" TABLE ACCESS FULL VAC_00008613 " " 3K"
" TABLE ACCESS FULL VLD_00008612 " " 4K"
" TABLE ACCESS FULL CCH_00008617 " " 8K"
" FILTER " " "
" HASH JOIN OUTER " " 1 "
" FILTER " " "
" HASH JOIN OUTER " " 1 "
" TABLE ACCESS FULL VLD_00008785 " " 14 "
" TABLE ACCESS FULL VAC_00008786 " " 11 "
" TABLE ACCESS FULL CCH_0000878A " " 74 "
" FILTER " " "
" HASH JOIN OUTER " " 1 "
" FILTER " " "
" HASH JOIN RIGHT OUTER " " 1 "
" TABLE ACCESS FULL VAC_000084B1 " " 11 "
" TABLE ACCESS FULL VLD_000084B0 " " 225 "
" TABLE ACCESS FULL CCH_000084B5 " " 1K"
" FILTER " " "
" HASH JOIN OUTER " " 1 "
" FILTER " " "
" HASH JOIN OUTER " " 1 "
" TABLE ACCESS FULL VLD_000085EE " " 1K"
" TABLE ACCESS FULL VAC_000085EF " " 3K"
" TABLE ACCESS FULL CCH_000085F3 " " 8K"

There's not much point in hiding the table name in v$session_longops if you then show us all the tablenames in the execution plan, moreover hiding the name makes it harder to help you because we've got no idea which table in the plan (which has many tablescans) is the one being reported.
v$session_longops includes the sql_plan_line_id, so you could post that with the rest of the information - and produce a better output for the plan - like calling dbms_xplan.display_cursor() with the SQL_ID that's reported in the v$session_longops and has a matching plan_hash_value. Try to find a tool that reports a flat text file, and the select the "Code Block" format option from the options on the left (click on the paragraph marker (backwards p) the "code block" before inserting the text).
Can you see the last_update_time increasing - how does the rate of increase compare with the rate of change of the SOFAR value - how about printing the time columns with a format that shows the time component. Given the length of time the query may have been running can you still find it with the SQL Monitor code to see where the time is going, and how many executions of other bits of the code have taken place. I think SQL Monitor will stopped monitoring (I think it's got a time limit built in) but if it hasn't can you see which bit of the plan is still executing. Is the client still alive ? Can you take a couple of snapshot of the session statistics for the SID and find out what it's doing - you may find (for example) that it's spending all it's time applying undo records, and if you snap the session_events you may find that the time is actually going on reading the undo tablespace.
Regards
Jonathan Lewis

explain-plan.pdf (51.82 KB)

select * from v$session_longops where sid=158;

SID SERIAL# OPNAME TARGET SOFAR TOTALWORK UNITS START_TIME LAST_UPDATE_TIME
158 41050 Table Scan VLD_00006D22 14718 204924 Blocks 13-OCT-22 13-OCT-22

TIME_REMAINING ELAPSED_SECONDS CONTEXT MESSAGE
60481 4680 0 Table Scan: VLD_00006D22: 14718 out of 204924 Blocks done

USERNAME SQL_ADDRESS SQL_HASH_VALUE SQL_ID SQL_PLAN_HASH_VALUE SQL_EXEC_START
PMMS 00000000A552E8F8 217081698 f1jxrdn6g0tv2 234046863 13-OCT-22

SQL_EXEC_ID SQL_PLAN_LINE_ID SQL_PLAN_OPERATION SQL_PLAN_OPTION QCSID CONID
16777216 22 TABLE ACCESS FULL 0 0

SELECT * FROM table(DBMS_XPLAN.DISPLAY_CURSOR('f1jxrdn6g0tv2',0));
output attached as pdf file

Can you see the last_update_time increasing - how does the rate of increase compare with the rate of change of the SOFAR value - how about printing the time columns with a format that shows the time component.
I should have been more precise in my request - by the "time" columns I meant start_time and last_update_time which are displaying only the date component.
You haven't said anything about the rates of change of time and blocks.
You haven't commented on the SQL Monitor suggestion
You haven't commented on the session statistics or wait events.
The execution plan is, however, readable - though as a general guideline most people on the forum avoid downloading attachments - but you've only shown part of the output and not shown the predicate information that should appear by default.

I can give you a hypothesis about the long time for the tablescan - but don't have enough information to be confident that it is correct. To set the scene - imagine you have a tablescan that selects a customer id from each row in a customers table, but the query includes a scalar subquery which, for each row, visits the orders and orderlines tables to calculate the total value of all orders placed by the customer in the last 12 months. The resources used in the tablescan itself will not be great, but there would be a long wait time between each multi-block read because of the number of evaluations of the scalar subquery; and it's that time that would show up in the v$session_longops as if it were the tablescan taking the time.
In those circumstances if you had the SQL Monitor report (or if you ran the query with with statistics_level set to all - or rowsource execution statistics enabled) you would get a plan that made this clear. (There's an example of this type of thing on my blog at this URL where the difference in time between operations 61 and 62 is due to the execution of the scalar subqueries and NOT to the work done by the hash join at operation 61.
SO -- in your case I'll extract a piece of the plan around operation 22:

15          NESTED LOOPS OUTER
16            FILTER
17              HASH JOIN RIGHT OUTER
18                VIEW
19                  HASH JOIN RIGHT ANTI SNA
20                    INDEX FULL SCAN SYS_C00364276
21                    TABLE ACCESS FULL VAC_00006D1B
22                TABLE ACCESS FULL VLD_00006D22
23            VIEW PUSHED PREDICATE

For this part of the plan the "top level" activity is - for each row from the filter at operation 16 get rows from the view at operation 23. This means the nested loop at operation 15 could take a very long time to complete even though Oracle could supply all the data from the sub-plan (16 - 22) very quickly if you wrote a query to do just that bit of the query. So the ELAPSED time for the tablescan at operation 22 to complete could be MUCH longer than the time spent doing the work of the tablescan.

Regards
Jonathan Lewis

(1) rate of change
select to_char(last_update_time, 'MM-DD-YYYY HH24:MI:SS') last_update_time,
to_char(start_time, 'MM-DD-YYYY HH24:MI:SS') start_time, sofar, totalwork
from v$session_longops where sid=158;

-----------------------------------------------------------------------------
last_update_time start_time sofar totalwork
-----------------------------------------------------------------------------
10-13-2022 12:46:37 10-13-2022 08:15:43 33364 204924

10-13-2022 12:48:37 10-13-2022 08:15:43 33552 204924
-----------------------------------------------------------------------------
The rate of change blocks is 188 in 120 seconds

2) I am using Oracle SQL Developer, not able to start Real time SQL Monitor, it is hanging

3) Waits

SELECT
s.sid,
s.serial#,
sw.event,
sw.wait_class,
sw.wait_time,
sw.seconds_in_wait,
sw.state
FROM v$session_wait sw,
v$session s
WHERE s.sid = sw.sid and s.sid=158;

158 41050 db file sequential read User I/O -1 0 WAITED SHORT TIME

I've written up a note about why a small tablescan could show up with a large elapsed time in v$session_longops on my blog. Since you're having trouble with the SQL Monitor tool you could query v$active_session_history (possibly dba_hist_active_sess_history) to get some details to support the hypothesis. This assumes you're licensed for the performance and diagnostic packs.
Querying v$session_event (not v$session_wait) would give you the summary of wait events; but we need details so we can check if a lot of those waits were for reads of undo tablespace; we could sample v$session_wait_history as the query progresses as that reports the last 10 waits for a session - if we're checking for undo reads we need only worry about seeing lots of db file sequential reads for files (p1 value) that match the undo tablespace files. v$sesstat (joined to v$sesstat) if the session is still live might tell us that a lot of buffer gets turned into "undo records" applied.

An alternative to the SQL Monitor if you can run the query again is set enable rowsource execution stats:

alter session set statistics_level = all;
--  execute query
select * from table(dbms_xplan.display_cursor('sql_id', format=>'allstats last'))

This will produce columns like "Starts" "A-Rows", "A-time" "Reads" that will tell you which lines really consumed most resources. Here's the URL an old note that covers this type of thing
Regards
Jonathan Lewis

Thank you for sharing blogs, it is helpful to see the insights.
The two views dba_hist_active_sess_history, v$active_session_history does not give any output.
As you mentioned, the SQL query has many subqueries in FROM clause.

select * from v$session_event where sid=158 order by total_waits desc;
158 db file sequential read 29169 0 1183 0.04 17 11834163 2652584166 1740759767 8 User I/O 0

select * from v$session_wait_history where sid=158;
158 1 164 db file sequential read file# 6 block# 2667320 blocks 1 0 22 310480 0
158 2 164 db file sequential read file# 6 block# 2692455 blocks 1 0 27 1413209 0
158 3 164 db file sequential read file# 4 block# 933241 blocks 1 0 22 2019649 0
158 4 164 db file sequential read file# 6 block# 2672964 blocks 1 0 41 1091607 0
158 5 164 db file sequential read file# 6 block# 2689272 blocks 1 0 15 1887442 0
158 6 226 direct path read file number 4 first dba 1608096 block cnt 16 0 52 270309 0
158 7 164 db file sequential read file# 6 block# 2679450 blocks 1 0 23 308988 0
158 8 164 db file sequential read file# 5 block# 4181593 blocks 1 0 22 2505440 0
158 9 164 db file sequential read file# 5 block# 4075353 blocks 1 0 22 777853 0
158 10 164 db file sequential read file# 4 block# 1373944 blocks 1 0 17 2934549 0

Thank you for providing lot of details in understanding the issue.