7 Replies Latest reply: Jul 30, 2010 2:40 PM by fechen RSS

    direct path write temp wait event on temp lob

    fechen
      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
          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
            Charles Hooper
            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
              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
                Charles Hooper
                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
                  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
                    Charles Hooper
                    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
                      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