Forum Stats

  • 3,759,222 Users
  • 2,251,514 Discussions
  • 7,870,539 Comments

Discussions

Query takes twice as long on DB than others with huge 'direct path read|write temp' waits

Sebino
Sebino Member Posts: 40 Red Ribbon
edited Jun 22, 2021 8:22AM in General Database Discussions

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

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,756 Gold Crown
    Accepted 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

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,756 Gold Crown

    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

  • Sebino
    Sebino Member Posts: 40 Red Ribbon

    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

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,756 Gold Crown
    Accepted 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

  • Sebino
    Sebino Member Posts: 40 Red Ribbon

    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.