RE: slow truncate, "db file parallel write" waits

From: Ravi Kulkarni <kulkarni.ravi_at_heb.com>
Date: Tue, 25 May 2004 08:49:19 -0500
Message-id: <0HY9005KRVPHUU@sys98048.heb.com>

Is your table wb_PROJ_RES_TMP 'monitored' ? I saw similar statements(accesses to mlog$ etc.) in the 10046 trace when monitored tables are TRUNCATEd. It does need to update the monitoring stats for the table when truncated.

Thanks,
Ravi.

-----Original Message-----

From: oracle-l-bounce_at_freelists.org
[mailto:oracle-l-bounce_at_freelists.org]On Behalf Of Wolfgang Breitling Sent: Monday, May 24, 2004 9:19 PM
To: oracle-l_at_freelists.org
Subject: slow truncate, "db file parallel write" waits

Hi everyone,

I hope someone can shed some light on this. Here is the situation: Oracle Release 9.2.0.2.0 on Sun Solaris 5.8. Tablespaces are LMT.

Truncates are taking exceptionally long. Today I was truncating a table after inserting 178301 rows (which took ~26 seconds) and it took over 2 minutes to truncate. While I was waiting for the truncate to finish I was looking at v$session_wait and saw repeated "db file parallel write" all with a p1 value of 204. However, the sql trace does not show any "db file parallel write"s but instead more than 2 minutes of "rdbms ipc reply", see below from the tkprof output:

Elapsed times include waiting on following events:

   Event waited on                             Times   Max. Wait  Total Waited
   ----------------------------------------   Waited  ----------  ------------
   SQL*Net message to client                       3        0.00          0.00
   SQL*Net message from client                     3       35.80         67.42
   SQL*Net break/reset to client                   1        0.00          0.00
   rdbms ipc reply                                71        2.00        141.16
   db file sequential read                         3        0.00          0.00
   local write wait                                1        0.08          0.08
   log file sync                                   1        0.03          0.03

And this is a section of the raw trace following the truncate:

PARSING IN CURSOR #1 len=30 dep=0 uid=23 oct=85 lid=23 tim=2284767565029 hv=322251856 ad='bf5aadd8'
truncate table wb_PROJ_RES_TMP
END OF STMT
PARSE #1:c=40000,e=41343,p=0,cr=0,cu=1,mis=1,r=0,dep=0,og=4,tim=2284767565007 BINDS #1:

PARSING IN CURSOR #2 len=105 dep=1 uid=0 oct=3 lid=0 tim=2284767565771 hv=3350194674 ad='ba716130'
select log, sysdate, sysdate+1/86400, flag from sys.mlog$ where mowner = :1 and master = :2 for update
END OF STMT

PARSE #2:c=0,e=170,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767565764
BINDS #2:
  bind 0: dty=1 mxl=32(06) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=32

offset=0

bfp=ffffffff7c8698e8 bln=32 avl=06 flg=05 value="SYSADM"
bind 1: dty=1 mxl=32(15) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=32 offset=0

bfp=ffffffff7c8698b0 bln=32 avl=15 flg=05 value="WB_PROJ_RES_TMP"
EXEC #2:c=0,e=636,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767566743

FETCH #2:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767566833
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='FOR UPDATE  (cr=0 r=0 w=0 time=2 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=170 op='TABLE ACCESS CLUSTER MLOG$ (cr=1

r=0 w=0 time=45 us)'
STAT #2 id=3 cnt=0 pid=2 pos=1 obj=169 op='INDEX UNIQUE SCAN I_MLOG# (cr=1 r=0 w=0 time=35 us)'

PARSING IN CURSOR #2 len=129 dep=1 uid=0 oct=3 lid=0 tim=2284767568748 hv=429969799 ad='bdeae2b8'
select n.intcol# from ntab$ n, col$ c where n.obj#=:1 and c.obj#=:1 and c.intcol#=n.intcol# and bitand(c.property, 32768)!=32768 END OF STMT

PARSE #2:c=0,e=128,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767568741
BINDS #2:
  bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24

offset=0

bfp=ffffffff7c8689b8 bln=22 avl=04 flg=05 value=533312
bind 1: (No oacdef for this bind)

EXEC #2:c=0,e=316,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767569331
FETCH #2:c=0,e=1783,p=0,cr=140,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767571179
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=140 r=0 w=0

time=1780 us)'
STAT #2 id=2 cnt=134 pid=1 pos=1 obj=21 op='TABLE ACCESS CLUSTER COL$ (cr=138 r=0 w=0 time=1206 us)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 r=0 w=0 time=41 us)'
STAT #2 id=4 cnt=0 pid=1 pos=2 obj=354 op='INDEX UNIQUE SCAN I_NTAB2 (cr=2 r=0 w=0 time=245 us)'

PARSING IN CURSOR #2 len=116 dep=1 uid=0 oct=3 lid=0 tim=2284767571969 hv=431456802 ad='b8dae190'
select
o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataobj#,o.flags from obj$ o where o.obj#=:1
END OF STMT

PARSE #2:c=0,e=133,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767571962
BINDS #2:
  bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24

offset=0

bfp=ffffffff7c864cd0 bln=22 avl=04 flg=05 value=533312
EXEC #2:c=0,e=249,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2284767572541 FETCH #2:c=0,e=80,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=2284767572687

WAIT #1: nam='rdbms ipc reply' ela= 2006563 p1=5 p2=21474836 p3=0
WAIT #1: nam='rdbms ipc reply' ela= 2001840 p1=5 p2=21474834 p3=0
WAIT #1: nam='rdbms ipc reply' ela= 2001801 p1=5 p2=21474832 p3=0
WAIT #1: nam='rdbms ipc reply' ela= 2001828 p1=5 p2=21474830 p3=0
WAIT #1: nam='rdbms ipc reply' ela= 2001836 p1=5 p2=21474828 p3=0

and so on.

regards

Wolfgang Breitling
Centrex Consulting Corporation
www.centrexcc.com

Please see the official ORACLE-L FAQ: http://www.orafaq.com

To unsubscribe send email to: oracle-l-request_at_freelists.org put 'unsubscribe' in the subject line.
--

Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html

Please see the official ORACLE-L FAQ: http://www.orafaq.com

Received on Tue May 25 2004 - 08:46:32 CDT