Discussions
Categories
- 197.1K All Categories
- 2.5K Data
- 546 Big Data Appliance
- 1.9K Data Science
- 450.7K Databases
- 221.9K General Database Discussions
- 3.8K Java and JavaScript in the Database
- 31 Multilingual Engine
- 552 MySQL Community Space
- 479 NoSQL Database
- 7.9K Oracle Database Express Edition (XE)
- 3.1K ORDS, SODA & JSON in the Database
- 555 SQLcl
- 4K SQL Developer Data Modeler
- 187.2K SQL & PL/SQL
- 21.3K SQL Developer
- 296.3K Development
- 17 Developer Projects
- 139 Programming Languages
- 293K Development Tools
- 110 DevOps
- 3.1K QA/Testing
- 646.1K Java
- 28 Java Learning Subscription
- 37K Database Connectivity
- 158 Java Community Process
- 105 Java 25
- 22.1K Java APIs
- 138.2K Java Development Tools
- 165.3K Java EE (Java Enterprise Edition)
- 19 Java Essentials
- 162 Java 8 Questions
- 86K Java Programming
- 81 Java Puzzle Ball
- 65.1K New To Java
- 1.7K Training / Learning / Certification
- 13.8K Java HotSpot Virtual Machine
- 94.3K Java SE
- 13.8K Java Security
- 204 Java User Groups
- 24 JavaScript - Nashorn
- Programs
- 466 LiveLabs
- 39 Workshops
- 10.2K Software
- 6.7K Berkeley DB Family
- 3.5K JHeadstart
- 5.7K Other Languages
- 2.3K Chinese
- 175 Deutsche Oracle Community
- 1.1K Español
- 1.9K Japanese
- 233 Portuguese
Query takes twice as long on DB than others with huge 'direct path read|write temp' waits
Hello,
We got a server with 18c databases (5 of them) where the same query (a select on a view) takes twice as long than on any other database on same server.
Underlying tables of this view have very similar volumes (even a little more in one where it's quicker), statistics are up-to-date; execution plan *is the same* everywhere too. All parameters are the same too (except CPU_COUNT=12 where it's "slow", it's 24 everywhere else).
If I run this select on view in a loop (I loop 5000 times) with a 10046 trace, grep'ing waits in resulting trace files shows the following (I did a "grep ^WAIT <trc file>|cut -d'=' -f2|sort|uniq -c")
for DB where it's slow:
1750857 'ASM IO for non-blocking poll' ela 1 'db file parallel read' ela 2 'db file scattered read' ela 1046 'db file sequential read' ela 652968 'direct path read temp' ela 106466 'direct path write temp' ela 10 'Disk file operations I/O' ela 1 'latch free' ela 16 'PGA memory operation' ela 4 'SQL*Net message from client' ela 4 'SQL*Net message to client' ela
for DBs where it's quicker, it always shows something similar to:
2 'db file parallel read' ela 1 'db file scattered read' ela 1430 'db file sequential read' ela 9 'Disk file operations I/O' ela 7 'PGA memory operation' ela 4 'SQL*Net message from client' ela 4 'SQL*Net message to client' ela
My question: where should I try to find the reason why that many direct path temp operations take place on "slow" database ?
Any suggestion ?
Thanks a lot...
Regards,
Sebino
Best Answer
-
The answer is in the data.
In the slow plan you get 9,098 rows from the PS_TL_DATES_TBL index in the last line of the plan (driven by 14 probes (starts=14) of the nested loop; this gives you a "window sort " in the 2nd line that spills to disc with 751 blocks written and read (pw= pr=).
In comparison the fast plan reports only 31 rows, and doesn't need to spill to disc for the window sort.
Those are the figures for one execution of the query, by the way.
I'd check the data to see if anything unusual had happened that could have affected a small section of the data; I'd also check that the view definitions were definitely the same. I'd also check the predicate information (which doesn't get into the trace file) for the two examples. It's possible that (for reasons we can't see) the way in which your predicates are used varies from one plan to another - even though the resulting plans shapes are identical; in particular maybe the slow plan manages to postpone using a predicate until the last moment.
You'll need to use dbms_xplan.display_cursor() to pull the plan from memory after running your test, passing in the SQL_ID that you can see in the tkprof output.
Regards
Jonathan Lewis
Answers
-
Run tkprof against the trace file for the slow run and one of the fast ones, and post the two "Row Source Operation" (execution plans) section for the statement from the two outputs.
The time and I/O stats information in the plans should tell us (and you) what activity is making those reads and writes appear, and may give you some idea why.
To make a readable fixed font output, click on the paragraphs symbol (backwards P) to the right of the edit box when you're about to paste the text, select the double quote from the menu that appears, and then the "Code Block" option from the secondary menu.
Regards
Jonathan Lewis
-
Where it's slow we have:
SQL ID: gy6y1fpjy50cz Plan Hash: 3925307117 SELECT TO_CHAR(FILL.BGN_DT,'dd-mon-yy'),TO_CHAR(FILL.END_DT,'dd-mon-yy'), FILL.SETID,FILL.SCH_ADHOC_IND,FILL.SCHEDULE_ID,FILL.SCHED_HRS_TOTAL, FILL.FG_HRSWEEK,FILL.FG_MAXHRSWEEK FROM PS_FG_HRSMONTH_VW FILL WHERE SETID = :B5 AND SCH_ADHOC_IND = :B4 AND SCHEDULE_ID = :B3 AND BGN_DT BETWEEN :B2 AND :B1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4998 0.65 0.65 0 0 0 0 Fetch 4998 1120.38 1358.44 3859439 2827053 194904 4997 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9997 1121.04 1359.09 3859439 2827053 194904 4997 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS (recursive depth: 1) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 VIEW (cr=344 pr=751 pw=751 time=256803 us starts=1 cost=10 size=292 card=4) 9098 9098 9098 WINDOW SORT (cr=344 pr=751 pw=751 time=195606 us starts=1 cost=10 size=508 card=4) 9098 9098 9098 NESTED LOOPS (cr=344 pr=0 pw=0 time=87945 us starts=1 cost=9 size=508 card=4) 14 14 14 HASH JOIN (cr=14 pr=0 pw=0 time=533 us starts=1 cost=7 size=119 card=1) 14 14 14 NESTED LOOPS (cr=14 pr=0 pw=0 time=508 us starts=1 cost=7 size=119 card=1) 1 1 1 STATISTICS COLLECTOR (cr=10 pr=0 pw=0 time=391 us starts=1) 1 1 1 VIEW (cr=10 pr=0 pw=0 time=355 us starts=1 cost=4 size=80 card=1) 1 1 1 WINDOW BUFFER (cr=10 pr=0 pw=0 time=352 us starts=1 cost=4 size=42 card=1) 1 1 1 FILTER (cr=10 pr=0 pw=0 time=294 us starts=1) 1 1 1 TABLE ACCESS BY INDEX ROWID PS_SCH_DEFN_TBL (cr=10 pr=0 pw=0 time=288 us starts=1 cost=4 size=42 card=1) 1 1 1 INDEX RANGE SCAN PS_SCH_DEFN_TBL (cr=9 pr=0 pw=0 time=269 us starts=1 cost=3 size=0 card=1)(object id 7666200) 14 14 14 TABLE ACCESS BY INDEX ROWID BATCHED PS_SCH_DEFN_DTL (cr=4 pr=0 pw=0 time=104 us starts=1 cost=3 size=39 card=1) 14 14 14 INDEX RANGE SCAN PS_SCH_DEFN_DTL (cr=3 pr=0 pw=0 time=75 us starts=1 cost=2 size=0 card=1)(object id 7644322) 0 0 0 TABLE ACCESS BY INDEX ROWID BATCHED PS_SCH_DEFN_DTL (cr=0 pr=0 pw=0 time=0 us starts=0 cost=3 size=39 card=1) 0 0 0 INDEX RANGE SCAN PS_SCH_DEFN_DTL (cr=0 pr=0 pw=0 time=0 us starts=0 cost=2 size=0 card=1)(object id 7644322) 9098 9098 9098 INDEX RANGE SCAN PS_TL_DATES_TBL (cr=330 pr=0 pw=0 time=85833 us starts=14 cost=2 size=56 card=7)(object id 7641021) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ PGA memory operation 14 0.00 0.00 ASM IO for non-blocking poll 1750857 0.00 6.34 direct path write temp 106466 0.05 90.25 direct path read temp 652968 0.05 151.44 Disk file operations I/O 6 0.00 0.00 db file sequential read 1019 0.01 0.63 latch free 1 0.00 0.00 db file scattered read 1 0.00 0.00 db file parallel read 1 0.00 0.00
Now two copy-pastes from databases where it is quicker:
SQL ID: gy6y1fpjy50cz Plan Hash: 3925307117 SELECT TO_CHAR(FILL.BGN_DT,'dd-mon-yy'),TO_CHAR(FILL.END_DT,'dd-mon-yy'), FILL.SETID,FILL.SCH_ADHOC_IND,FILL.SCHEDULE_ID,FILL.SCHED_HRS_TOTAL, FILL.FG_HRSWEEK,FILL.FG_MAXHRSWEEK FROM PS_FG_HRSMONTH_VW FILL WHERE SETID = :B5 AND SCH_ADHOC_IND = :B4 AND SCHEDULE_ID = :B3 AND BGN_DT BETWEEN :B2 AND :B1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4998 0.31 0.31 0 0 0 0 Fetch 4998 644.43 646.75 1430 2827030 0 4997 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9997 644.74 647.06 1430 2827030 0 4997 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS (recursive depth: 1) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 VIEW (cr=183 pr=29 pw=0 time=72180 us starts=1 cost=10 size=70 card=1) 31 31 31 WINDOW SORT (cr=183 pr=29 pw=0 time=72178 us starts=1 cost=10 size=126 card=1) 31 31 31 NESTED LOOPS (cr=183 pr=29 pw=0 time=15335 us starts=1 cost=9 size=126 card=1) 7 7 7 HASH JOIN (cr=14 pr=4 pw=0 time=4078 us starts=1 cost=7 size=118 card=1) 7 7 7 NESTED LOOPS (cr=14 pr=4 pw=0 time=4045 us starts=1 cost=7 size=118 card=1) 1 1 1 STATISTICS COLLECTOR (cr=10 pr=0 pw=0 time=295 us starts=1) 1 1 1 VIEW (cr=10 pr=0 pw=0 time=265 us starts=1 cost=4 size=80 card=1) 1 1 1 WINDOW BUFFER (cr=10 pr=0 pw=0 time=261 us starts=1 cost=4 size=41 card=1) 1 1 1 FILTER (cr=10 pr=0 pw=0 time=215 us starts=1) 1 1 1 TABLE ACCESS BY INDEX ROWID PS_SCH_DEFN_TBL (cr=10 pr=0 pw=0 time=213 us starts=1 cost=4 size=41 card=1) 1 1 1 INDEX RANGE SCAN PS_SCH_DEFN_TBL (cr=9 pr=0 pw=0 time=199 us starts=1 cost=3 size=0 card=1)(object id 3067514) 7 7 7 TABLE ACCESS BY INDEX ROWID BATCHED PS_SCH_DEFN_DTL (cr=4 pr=4 pw=0 time=3736 us starts=1 cost=3 size=38 card=1) 7 7 7 INDEX RANGE SCAN PS_SCH_DEFN_DTL (cr=3 pr=3 pw=0 time=2491 us starts=1 cost=2 size=0 card=1)(object id 3045339) 0 0 0 TABLE ACCESS BY INDEX ROWID BATCHED PS_SCH_DEFN_DTL (cr=0 pr=0 pw=0 time=0 us starts=0 cost=3 size=38 card=1) 0 0 0 INDEX RANGE SCAN PS_SCH_DEFN_DTL (cr=0 pr=0 pw=0 time=0 us starts=0 cost=2 size=0 card=1)(object id 3045339) 31 31 31 INDEX RANGE SCAN PS_TL_DATES_TBL (cr=169 pr=25 pw=0 time=26768 us starts=7 cost=2 size=8 card=1)(object id 3042225) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ PGA memory operation 5 0.00 0.00 Disk file operations I/O 5 0.00 0.00 db file sequential read 1424 0.02 0.86 db file parallel read 2 0.00 0.00 db file scattered read 1 0.00 0.00
or:
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4998 0.33 0.33 0 0 1 0 Fetch 4998 653.99 655.64 1096 2826998 0 4997 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9997 654.33 655.97 1096 2826998 1 4997 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS (recursive depth: 1) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 VIEW (cr=507 pr=36 pw=0 time=157801 us starts=1 cost=10 size=70 card=1) 31 31 31 WINDOW SORT (cr=507 pr=36 pw=0 time=157794 us starts=1 cost=10 size=126 card=1) 31 31 31 NESTED LOOPS (cr=507 pr=36 pw=0 time=476234 us starts=1 cost=9 size=126 card=1) 21 21 21 HASH JOIN (cr=16 pr=11 pw=0 time=11143 us starts=1 cost=7 size=118 card=1) 21 21 21 NESTED LOOPS (cr=16 pr=11 pw=0 time=11029 us starts=1 cost=7 size=118 card=1) 1 1 1 STATISTICS COLLECTOR (cr=10 pr=6 pw=0 time=6610 us starts=1) 1 1 1 VIEW (cr=10 pr=6 pw=0 time=6577 us starts=1 cost=4 size=80 card=1) 1 1 1 WINDOW BUFFER (cr=10 pr=6 pw=0 time=6573 us starts=1 cost=4 size=41 card=1) 1 1 1 FILTER (cr=10 pr=6 pw=0 time=6525 us starts=1) 1 1 1 TABLE ACCESS BY INDEX ROWID PS_SCH_DEFN_TBL (cr=10 pr=6 pw=0 time=6521 us s tarts=1 cost=4 size=41 card=1) 1 1 1 INDEX RANGE SCAN PS_SCH_DEFN_TBL (cr=9 pr=5 pw=0 time=5559 us starts=1 cost=3 size=0 card=1)(object id 3791849) 21 21 21 TABLE ACCESS BY INDEX ROWID BATCHED PS_SCH_DEFN_DTL (cr=6 pr=5 pw=0 time=4382 us starts=1 cost=3 size=38 card=1) 21 21 21 INDEX RANGE SCAN PS_SCH_DEFN_DTL (cr=4 pr=4 pw=0 time=3235 us starts=1 cost=2 size=0 card=1)(object id 3769825) 0 0 0 TABLE ACCESS BY INDEX ROWID BATCHED PS_SCH_DEFN_DTL (cr=0 pr=0 pw=0 time=0 us starts=0 cost=3 size=38 card=1) 0 0 0 INDEX RANGE SCAN PS_SCH_DEFN_DTL (cr=0 pr=0 pw=0 time=0 us starts=0 cost=2 size=0 card=1)(object id 3769825) 31 31 31 INDEX RANGE SCAN PS_TL_DATES_TBL (cr=491 pr=25 pw=0 time=138911 us starts=21 cost=2 size=8 card=1)(object id 3766734) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ PGA memory operation 2 0.00 0.00 Disk file operations I/O 7 0.00 0.00 db file sequential read 1096 0.00 0.63
Thanks.
Sebino
-
The answer is in the data.
In the slow plan you get 9,098 rows from the PS_TL_DATES_TBL index in the last line of the plan (driven by 14 probes (starts=14) of the nested loop; this gives you a "window sort " in the 2nd line that spills to disc with 751 blocks written and read (pw= pr=).
In comparison the fast plan reports only 31 rows, and doesn't need to spill to disc for the window sort.
Those are the figures for one execution of the query, by the way.
I'd check the data to see if anything unusual had happened that could have affected a small section of the data; I'd also check that the view definitions were definitely the same. I'd also check the predicate information (which doesn't get into the trace file) for the two examples. It's possible that (for reasons we can't see) the way in which your predicates are used varies from one plan to another - even though the resulting plans shapes are identical; in particular maybe the slow plan manages to postpone using a predicate until the last moment.
You'll need to use dbms_xplan.display_cursor() to pull the plan from memory after running your test, passing in the SQL_ID that you can see in the tkprof output.
Regards
Jonathan Lewis
-
Gaargll... You were right - view definition differs in DB where it's slower, from all other...
(yet of course I was told by developers -or architects or whatever...- "schema is the same everywhere, we modified nothing"... etc. - as usual)
Thanks Jonathan.