slow truncate, "db file parallel write" waits
- From: Wolfgang Breitling <breitliw@xxxxxxxxxxxxx>
- To: oracle-l@xxxxxxxxxxxxx
- Date: Mon, 24 May 2004 20:18:49 -0600
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@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
Other related posts:
