This discussion is archived
7 Replies Latest reply: Jul 30, 2010 12:40 PM by fechen RSS

direct path write temp wait event on temp lob

fechen Newbie
Currently Being Moderated
We have an operation that involves the following: read lobs from a table, decompress it, write the decompressed data into temp lobs, then process the data in the temp lobs and write the processed data into other temp lobs, at the end, compress the data in the temp lob of last step and write to permanent lob. So there are a lot of lob reading and writing. The problem is the execution time of the operation's first invocation is 2-3 times of the following invocations. Here "the following invocations" could be in the same session or after the database is shutdown or restarted. The difference doesn't seem to be caused by the caching or buffering.

I generated AWR report for both cases. I found that the first invocation has long "direct path write temp" wait time as follows:

First invocation:
Event     Waits     Time(s)     Avg wait (ms)     % DB time     Wait Class
direct path write temp     7,719     79     10     64.53     User I/O
DB CPU          25          20.52     
direct path read temp     18,235     0     0     0.39     User I/O
local write wait     744     0     1     0.34     User I/O
db file sequential read     23,260     0     0     0.28     User I/O

later invocation:
Event     Waits     Time(s)     Avg wait (ms)     % DB time     Wait Class
DB CPU          36          61.25     
direct path write temp     7,914     11     1     18.37     User I/O
sort segment request     1     1     982     1.67     Configuration
db file sequential read     25,616     1     0     1.42     User I/O
direct path read temp     18,289     0     0     0.79     User I/O

Could anyone shed some lights on this? What could have caused this difference?

Thanks,
  • 1. Re: direct path write temp wait event on temp lob
    BelMan Expert
    Currently Being Moderated
    Tune away the direct path read temp
    High disk sorts – The disk sort distribution can be checked:


    select a.instance_number,to_char(a.snap_time,'dd/mon/yyyy hh24:mi') meas_date, b.value
    from stats$snapshot a, stats$sysstat b, v$statname c
    where c.name='sorts (disk)'
    and a.snap_time>sysdate-7
    and c.statistic#=b.statistic#
    and b.snap_id=a.snap_id
    order by a.instance_number,a.snap_time

    It is recommended to use pga_aggregate_target. This area is used both for sorts and the hash join area. If possible the PGA can be sized larger to fit more in-memory sorts reducing the disk sorts. It is important to remember that there are limitations of pga_aggregate_target: The total work area cannot exceed 200 megabytes of RAM because of the default setting for the hidden parameter_pga_max_size. No RAM sort may use more than 5% of pga_aggregate_target or pgamax_size, whichever is smaller. This means that no task may use more than 200 megabytes for sorting or hash joins. Oracle does not recommend changing the hidden parameters, but for certain environments, the result can be beneficial.

    To view the PGA and its distribution.

    Select * from v$pgastat;
    NAME VALUE
    ---------------------------------------- ----------
    aggregate PGA target parameter
    aggregate PGA auto target
    global memory bound
    total PGA inuse
    total PGA allocated
    maximum PGA allocated
    total freeable PGA memory
    PGA memory freed back to OS
    total PGA used for auto workareas
    maximum PGA used for auto workareas
    total PGA used for manual workareas
    maximum PGA used for manual workareas
    over allocation count
    bytes processed
    extra bytes read/written
    cache hit percentage

    Tune the sorts – Find the session experiencing the waits and look at the SQL statement currently being run to see the cause of the sorts. Query V$TEMPSEG_USAGE to find the SQL statement generating the sort. Also query the statistics from V$SESSTAT for the session to determine the size of the sort. Determine whether it is possible to reduce the sorting by tuning the SQL statement.
    Full Table Scans – If tables are defined with a high degree of parallelism, the optimizer leans towards using full table scans with parallel slaves. For a direct path read, locate the object being loaded. Consider using disk striping or Automatic Storage Management (ASM) which can stripe for you.
    Parallel DML – Check the I/O distribution across the disks and make sure your I/O is configured for the parallelism being used. Verify that the parameter DISK_ASYNCH_IO is set to true.
  • 2. Re: direct path write temp wait event on temp lob
    CharlesHooper Expert
    Currently Being Moderated
    BelMan wrote:
    Tune away the direct path read temp
    High disk sorts – The disk sort distribution can be checked:


    select a.instance_number,to_char(a.snap_time,'dd/mon/yyyy hh24:mi') meas_date, b.value
    from stats$snapshot a, stats$sysstat b, v$statname c
    where c.name='sorts (disk)'
    and a.snap_time>sysdate-7
    and c.statistic#=b.statistic#
    and b.snap_id=a.snap_id
    order by a.instance_number,a.snap_time
    (snip)

    BelMan,

    It was generous of you to perform a search for the original poster on this particular wait event.

    However, please always provide a link to the original article, and indicate that you are copying/quoting from an article. If appears that you copied from one of the following links:
    http://www.confio.com/English/Tips/Direct_Path_Read_Temp.php
    http://support.confio.com/blog/post/oracle-wait-event-explained-direct-path-read-temp/22/

    It does not appear that the section that you copied applies to the original poster in this case.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 3. Re: direct path write temp wait event on temp lob
    fechen Newbie
    Currently Being Moderated
    Thanks for the reply. However I think the problem is in "direct path write temp", not "direct path read temp". In the two reports, the time on "direct path write temp" is 79s and 11s respectively. The only different is one is the first run and the other one is the second run (after restart db). In addition, I don't have large sort.
  • 4. Re: direct path write temp wait event on temp lob
    CharlesHooper Expert
    Currently Being Moderated
    First invocation:
    Event                       Waits   Time(s)  Avg wait (ms)  % DB time    Wait Class
    direct path write temp      7,719        79             10      64.53    User I/O
    DB CPU                                   25                     20.52     
    direct path read temp      18,235         0              0       0.39    User I/O
    local write wait              744         0              1       0.34    User I/O
    db file sequential read    23,260         0              0       0.28    User I/O
    
    later invocation:
    Event                       Waits   Time(s)   Avg wait (ms) % DB time    Wait Class
    DB CPU                                   36                     61.25     
    direct path write temp      7,914        11               1     18.37    User I/O
    sort segment request            1         1             982      1.67    Configuration
    db file sequential read    25,616         1               0      1.42    User I/O
    direct path read temp      18,289         0               0      0.79    User I/O
    It is very difficult to read the output that you provided due to the elimination of the spaces, so I have re-posted it above. Please use a { code } tag (without spaces) before and after the sections of your post where the spaces are critical for understanding.

    There is not a lot of information in what you provided. Is the process using global temporary tables?

    This is an interesting Oracle-L thread that might apply to your case - I notice that there were 744 very quick "local write wait" waits in the first invocation and none in the second:
    http://www.freelists.org/post/oracle-l/local-write-wait-event,7

    Part of the problem with relying on the AWR report is that the data displayed is not constrained to only the process that you are attempting to monitor. Enable a 10046 trace at level 8 or 12 for the session and then review the trace file to see why that session is waiting.

    This is part one of a two part series that describes how to enable a 10046 trace:
    http://hoopercharles.wordpress.com/2009/12/01/10046-extended-sql-trace-interpretation/

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 5. Re: direct path write temp wait event on temp lob
    fechen Newbie
    Currently Being Moderated
    Charles, thank you for formatting my post and your suggestions. I enabled the 10046 trace. The "direct path write temp" events and "local write wait" events don't seem to be part of any execution of the sql statement. Here is a segment of the trace file:
    PARSE #3070392336:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=968792012,tim=1279906660314688
    EXEC #3070392336:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=968792012,tim=1279906660314778
    FETCH #3070392336:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,plh=968792012,tim=1279906660314833
    CLOSE #3070392336:c=0,e=8,dep=2,type=3,tim=1279906660314911
    WAIT #3062272096: nam='db file sequential read' ela= 23 file#=6 block#=33058 blocks=1 obj#=66172 tim=1279906660320639
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33074 blocks=1 obj#=66172 tim=1279906660320701
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33090 blocks=1 obj#=66172 tim=1279906660320751
    WAIT #3062272096: nam='db file sequential read' ela= 12 file#=6 block#=33106 blocks=1 obj#=66172 tim=1279906660320799
    WAIT #3062272096: nam='direct path write temp' ela= 8599 file number=202 first dba=12 block cnt=4 obj#=104 tim=1279906660332153
    WAIT #3062272096: nam='db file sequential read' ela= 19 file#=6 block#=33122 blocks=1 obj#=66172 tim=1279906660332496
    WAIT #3062272096: nam='db file sequential read' ela= 12 file#=6 block#=33138 blocks=1 obj#=66172 tim=1279906660332562
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33154 blocks=1 obj#=66172 tim=1279906660332613
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33170 blocks=1 obj#=66172 tim=1279906660332680
    WAIT #3062272096: nam='direct path write temp' ela= 6807 file number=202 first dba=16 block cnt=4 obj#=104 tim=1279906660340073
    WAIT #3062272096: nam='db file sequential read' ela= 16 file#=6 block#=33186 blocks=1 obj#=66172 tim=1279906660340266
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33202 blocks=1 obj#=66172 tim=1279906660340337
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33218 blocks=1 obj#=66172 tim=1279906660340389
    WAIT #3062272096: nam='db file sequential read' ela= 12 file#=6 block#=33234 blocks=1 obj#=66172 tim=1279906660340438
    WAIT #3062272096: nam='asynch descriptor resize' ela= 2 outstanding #aio=0 current aio limit=195 new aio limit=198 obj#=104 tim=1279906660340849
    WAIT #3062272096: nam='direct path write temp' ela= 8987 file number=202 first dba=20 block cnt=4 obj#=104 tim=1279906660350058
    WAIT #3062272096: nam='db file sequential read' ela= 24 file#=7 block#=148 blocks=1 obj#=66173 tim=1279906660350332
    WAIT #3062272096: nam='db file sequential read' ela= 21 file#=6 block#=86 blocks=1 obj#=66173 tim=1279906660350423
    WAIT #3062272096: nam='db file sequential read' ela= 20 file#=6 block#=33250 blocks=1 obj#=66172 tim=1279906660350590
    WAIT #3062272096: nam='db file sequential read' ela= 19 file#=6 block#=33266 blocks=1 obj#=66172 tim=1279906660350681
    WAIT #3062272096: nam='db file sequential read' ela= 29 file#=6 block#=33282 blocks=1 obj#=66172 tim=1279906660350777
    WAIT #3062272096: nam='db file sequential read' ela= 19 file#=6 block#=33043 blocks=1 obj#=66172 tim=1279906660350882
    WAIT #3062272096: nam='asynch descriptor resize' ela= 3 outstanding #aio=0 current aio limit=198 new aio limit=210 obj#=104 tim=1279906660351455
    WAIT #3062272096: nam='asynch descriptor resize' ela= 3 outstanding #aio=0 current aio limit=210 new aio limit=214 obj#=104 tim=1279906660351545
    WAIT #3062272096: nam='db file sequential read' ela= 44 file#=202 block#=3 blocks=1 obj#=0 tim=1279906660351948
    WAIT #3062272096: nam='local write wait' ela= 15743 file#=202 block#=2 p3=0 obj#=1 tim=1279906660370451
    WAIT #3062272096: nam='local write wait' ela= 1331 file#=202 block#=3 p3=0 obj#=0 tim=1279906660371860
    WAIT #3062272096: nam='local write wait' ela= 194 file#=202 block#=2 p3=0 obj#=1 tim=1279906660372157
    WAIT #3062272096: nam='direct path write temp' ela= 7633 file number=202 first dba=24 block cnt=4 obj#=1 tim=1279906660380077
    There are a lot of temp lob reading and writing in my operation. Could these waits are on temp lob writing? But this doesn't explain why the first run and second run are different.

    Thanks,
    -Fengting
  • 6. Re: direct path write temp wait event on temp lob
    CharlesHooper Expert
    Currently Being Moderated
    Fengting,

    A couple of problems. I passed the section of the trace file that you provided to me through a trace file parser:
    Cursor 0   Ver 0   Parse at 1279906660.314690 (Parse to Parse 1279906660.314690), Goal=CHOOSE
    Cursor 0   Ver 0 Execute at 1279906660.314780 (Parse to Exec  1279906660.314780)
    Cursor 0   Ver 0   Fetch at 1279906660.314830 (Parse to Fetch 1279906660.314830)
    Cursor 0   Ver 0            1279906660.320640  0.000023   db file sequential read
    Cursor 0   Ver 0            1279906660.320700  0.000013   db file sequential read
    Cursor 0   Ver 0            1279906660.320750  0.000013   db file sequential read
    Cursor 0   Ver 0            1279906660.320800  0.000012   db file sequential read
    Cursor 0   Ver 0            1279906660.332150  0.008599   direct path write temp
    Cursor 0   Ver 0            1279906660.332500  0.000019   db file sequential read
    Cursor 0   Ver 0            1279906660.332560  0.000012   db file sequential read
    Cursor 0   Ver 0            1279906660.332610  0.000013   db file sequential read
    Cursor 0   Ver 0            1279906660.332680  0.000013   db file sequential read
    Cursor 0   Ver 0            1279906660.340070  0.006807   direct path write temp
    Cursor 0   Ver 0            1279906660.340270  0.000016   db file sequential read
    Cursor 0   Ver 0            1279906660.340340  0.000013   db file sequential read
    Cursor 0   Ver 0            1279906660.340390  0.000013   db file sequential read
    Cursor 0   Ver 0            1279906660.340440  0.000012   db file sequential read
    Cursor 0   Ver 0            1279906660.340850  0.000002   asynch descriptor resize
    Cursor 0   Ver 0            1279906660.350060  0.008987   direct path write temp
    Cursor 0   Ver 0            1279906660.350330  0.000024   db file sequential read
    Cursor 0   Ver 0            1279906660.350420  0.000021   db file sequential read
    Cursor 0   Ver 0            1279906660.350590  0.000020   db file sequential read
    Cursor 0   Ver 0            1279906660.350680  0.000019   db file sequential read
    Cursor 0   Ver 0            1279906660.350780  0.000029   db file sequential read
    Cursor 0   Ver 0            1279906660.350880  0.000019   db file sequential read
    Cursor 0   Ver 0            1279906660.351450  0.000003   asynch descriptor resize
    Cursor 0   Ver 0            1279906660.351550  0.000003   asynch descriptor resize
    Cursor 0   Ver 0            1279906660.351950  0.000044   db file sequential read
    Cursor 0   Ver 0            1279906660.370450  0.015743   local write wait
    Cursor 0   Ver 0            1279906660.371860  0.001331   local write wait
    Cursor 0   Ver 0            1279906660.372160  0.000194   local write wait
    Cursor 0   Ver 0            1279906660.380080  0.007633   direct path write temp
    The trace file parser indicates that the OPTIMIZER_MODE is set to CHOOSE - that could be part of the problem. Based on the presence of the CLOSE line in the trace file, you are running Oracle 11.1.0.6 or greater, which was released long after the CHOOSE parameter value was deprecated.

    * Second, a typical trace file looks something like this:
    PARSING IN CURSOR #9 len=210 dep=1 uid=0 oct=3 lid=0 tim=5884684690220 hv=864012087 ad='28dbfb78' sqlid='96g93hntrzjtr'
    select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
    END OF STMT
    EXEC #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=5884684690220
    FETCH #9:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=5884684690220
    CLOSE #9:c=0,e=0,dep=1,type=3,tim=5884684690220
    =====================
    PARSING IN CURSOR #14 len=51 dep=0 uid=60 oct=3 lid=60 tim=5884684690220 hv=1321303491 ad='23b698b8' sqlid='fnk3z1j7c2zf3'
    SELECT
      C1,
      C2,
      C3
    FROM
      T1
    WHERE
      C1<=50000
    END OF STMT
    PARSE #14:c=31250,e=43048,p=0,cr=140,cu=0,mis=1,r=0,dep=0,og=1,plh=3617692013,tim=5884684690220
    EXEC #14:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3617692013,tim=5884684690220
    WAIT #14: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=86190 tim=5884684699654
    WAIT #14: nam='reliable message' ela= 83 channel context=673578616 channel handle=673516600 broadcast message=674517632 obj#=86190 tim=5884684699872
    WAIT #14: nam='direct path read' ela= 10618 file number=5 first dba=1321963 block cnt=5 obj#=86190 tim=5884684710781
    FETCH #14:c=0,e=9650,p=13,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3617692013,tim=5884684699870
    WAIT #14: nam='SQL*Net message from client' ela= 298 driver id=1413697536 #bytes=1 p3=0 obj#=86190 tim=5884684711165
    WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=86190 tim=5884684711210
    FETCH #14:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=3617692013,tim=5884684699870
    WAIT #14: nam='SQL*Net message from client' ela= 1371 driver id=1413697536 #bytes=1 p3=0 obj#=86190 tim=5884684712634
    WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=86190 tim=5884684712667
    FETCH #14:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=3617692013,tim=5884684699870
    Notice how small the number is following PARSE, FETCH, and WAIT. Every time a new cursor is opened (and the previous cursor is not closed) the number after PARSE, FETCH, and WAIT is typically bumped up by 1 when the next SQL statement is executed (the numbers for previously opened cursors are not affected). This sequence is reset back to 1 (or maybe 0) when a session disconnects and reconnects. The numbers from trace file look like this in contrast:
    PARSE #3070392336:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=968792012,tim=1279906660314688
    EXEC #3070392336:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=968792012,tim=1279906660314778
    FETCH #3070392336:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,plh=968792012,tim=1279906660314833
    CLOSE #3070392336:c=0,e=8,dep=2,type=3,tim=1279906660314911
    WAIT #3062272096: nam='db file sequential read' ela= 23 file#=6 block#=33058 blocks=1 obj#=66172 tim=1279906660320639
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33074 blocks=1 obj#=66172 tim=1279906660320701
    WAIT #3062272096: nam='db file sequential read' ela= 13 file#=6 block#=33090 blocks=1 obj#=66172 tim=1279906660320751
    WAIT #3062272096: nam='db file sequential read' ela= 12 file#=6 block#=33106 blocks=1 obj#=66172 tim=1279906660320799
    WAIT #3062272096: nam='direct path write temp' ela= 8599 file number=202 first dba=12 block cnt=4 obj#=104 tim=1279906660332153
    Either your code that is executing during the trace has a serious cursor leak or something is wrong with the tracing facility in Oracle Database. How large is your OPEN_CURSORS parameter? And for that matter what other non-default parameters are you using?

    * Third, in the trace file section that you provided, we are actually looking at the information for two different cursors - the PARSE, EXEC, FETCH, and CLOSE entries are for one cursor and the WAIT events are for an entirely different cursor.

    * Fourth, I see the "asynch descriptor resize" wait event. I suggest that you take a look at all of the posts in these threads and the referenced Metalink article - you may need to make a change to the operating system parameters:
    http://www.freelists.org/post/oracle-l/asynch-descriptor-resize-wait-event,1
    Re: Async Descriptor Resize

    * Fifth, the time required for the single block reads is extremely small, very likely indicating that the reads are coming from some sort of cache (OS file system cache, SAN cache, etc.). Now compare that time with the time required to perform the direct path writes: 6ms to 9ms which likely indicates an actual physical write. Is it possible that your system is not caching writes (only do this if a battery will allow the data to survive a restart/crash of the server)?

    * Sixth, it appears that only 4 blocks are written at a time to the temp tablespace. What is the exent size of that tablespace, and what is the block size (this may be completely unrelated)?

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 7. Re: direct path write temp wait event on temp lob
    fechen Newbie
    Currently Being Moderated
    Hi Charles,

    I see the problems you observed. But they don't seem to be the cause for the difference of two runs. The two invocations ran under the same optimize_mode and setting. Both rans have a lot of 'direct path write temp' wait events. But the first run just spent much more time on the events. The wait event was on cursor:
    PARSING IN CURSOR #3062272096 len=562 dep=1 uid=79 oct=47 lid=79 tim=1279906658624490 hv=3663173449 ad='23f833a4' sqlid='fcq1h73d5g5u9'
    declare
     err_msg VARCHAR2(1000); 
     err_num NUMBER; 
     msg VARCHAR2(5000); 
     idx NUMBER;
     begin
     err_msg := mdsys.sdo_geor_aux.decompressData('DEFLATE', :1, :2, null, null, null, null); 
     if upper(err_msg) <> 'NONE' THEN idx := INSTR(err_msg, ';', 1, 1); 
     err_num := TO_NUMBER(SUBSTR(err_msg, 1, idx-1)); 
     DBMS_OUTPUT.PUT_LINE(err_num); 
     if (LENGTH(err_msg) - idx) > 0 then 
      msg := SUBSTR(err_msg, idx+1, LENGTH(err_msg)-idx+1); 
     mdsys.sdo_geor_aux.raiseErrorWithMsg(err_num, msg); 
     else mdsys.sdo_geor_aux.raiseError(err_num); 
     end if; 
     end if; 
     end; 
     
    END OF STMT
    I know that this pl/sql block is using java stored procedure to decompress data in persistent blob into temp blob. This definitely involves a lot of read/write. But why the first run waited longer? The second run is always faster even after I restarted the database. What could cause this difference?

    Thanks,
    -Fengting