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

  • From: "Khedr, Waleed" <Waleed.Khedr@xxxxxxx>
  • To: <oracle-l@xxxxxxxxxxxxx>
  • Date: Tue, 25 May 2004 08:50:51 -0400

What is process 5 in your system? From v$process?

It's usually something that has to do with checkpoint process: too many
of them, slow disks that slow checkpoint, etc.

Waleed

-----Original Message-----
From: Wolfgang Breitling [mailto:breitliw@xxxxxxxxxxxxx]=20
Sent: Monday, May 24, 2004 10:19 PM
To: oracle-l@xxxxxxxxxxxxx
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.=20
Tablespaces are LMT.

Truncates are taking exceptionally long. Today I was truncating a table=20
after inserting 178301 rows (which took ~26 seconds) and it took over 2=20
minutes to truncate. While I was waiting for the truncate to finish I
was=20
looking at v$session_wait and saw repeated "db file parallel write" all=20
with a p1 value of 204. However, the sql trace does not show any "db
file=20
parallel write"s but instead more than 2 minutes of "rdbms ipc reply",
see=20
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=3D30 dep=3D0 uid=3D23 oct=3D85 lid=3D23 =
tim=3D2284767565029

hv=3D322251856 ad=3D'bf5aadd8'
truncate table wb_PROJ_RES_TMP
END OF STMT
PARSE
#1:c=3D40000,e=3D41343,p=3D0,cr=3D0,cu=3D1,mis=3D1,r=3D0,dep=3D0,og=3D4,t=
im=3D2284767565007
BINDS #1:
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
PARSING IN CURSOR #2 len=3D105 dep=3D1 uid=3D0 oct=3D3 lid=3D0 =
tim=3D2284767565771=20
hv=3D3350194674 ad=3D'ba716130'
select log, sysdate, sysdate+1/86400, flag from sys.mlog$   where
mowner =3D=20
:1 and master =3D :2 for update
END OF STMT
PARSE =
#2:c=3D0,e=3D170,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D2=
284767565764
BINDS #2:
  bind 0: dty=3D1 mxl=3D32(06) mal=3D00 scl=3D00 pre=3D00 oacflg=3D18 =
oacfl2=3D1
size=3D32=20
offset=3D0
    bfp=3Dffffffff7c8698e8 bln=3D32 avl=3D06 flg=3D05
    value=3D"SYSADM"
  bind 1: dty=3D1 mxl=3D32(15) mal=3D00 scl=3D00 pre=3D00 oacflg=3D18 =
oacfl2=3D1
size=3D32=20
offset=3D0
    bfp=3Dffffffff7c8698b0 bln=3D32 avl=3D15 flg=3D05
    value=3D"WB_PROJ_RES_TMP"
EXEC =
#2:c=3D0,e=3D636,p=3D0,cr=3D1,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D2=
284767566743
FETCH =
#2:c=3D0,e=3D7,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D228=
4767566833
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'FOR UPDATE  (cr=3D0 =
r=3D0 w=3D0
time=3D2 us)'
STAT #2 id=3D2 cnt=3D0 pid=3D1 pos=3D1 obj=3D170 op=3D'TABLE ACCESS =
CLUSTER MLOG$
(cr=3D1=20
r=3D0 w=3D0 time=3D45 us)'
STAT #2 id=3D3 cnt=3D0 pid=3D2 pos=3D1 obj=3D169 op=3D'INDEX UNIQUE SCAN =
I_MLOG#
(cr=3D1=20
r=3D0 w=3D0 time=3D35 us)'
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
PARSING IN CURSOR #2 len=3D129 dep=3D1 uid=3D0 oct=3D3 lid=3D0 =
tim=3D2284767568748=20
hv=3D429969799 ad=3D'bdeae2b8'
select n.intcol# from ntab$ n, col$ c  where n.obj#=3D:1 and c.obj#=3D:1 =
and

c.intcol#=3Dn.intcol# and bitand(c.property, 32768)!=3D32768
END OF STMT
PARSE =
#2:c=3D0,e=3D128,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D2=
284767568741
BINDS #2:
  bind 0: dty=3D2 mxl=3D22(22) mal=3D00 scl=3D00 pre=3D00 oacflg=3D08 =
oacfl2=3D1
size=3D24=20
offset=3D0
    bfp=3Dffffffff7c8689b8 bln=3D22 avl=3D04 flg=3D05
    value=3D533312
  bind 1: (No oacdef for this bind)
EXEC =
#2:c=3D0,e=3D316,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D2=
284767569331
FETCH
#2:c=3D0,e=3D1783,p=3D0,cr=3D140,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D=
2284767571179
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'NESTED LOOPS  =
(cr=3D140 r=3D0 w=3D0=20
time=3D1780 us)'
STAT #2 id=3D2 cnt=3D134 pid=3D1 pos=3D1 obj=3D21 op=3D'TABLE ACCESS =
CLUSTER COL$=20
(cr=3D138 r=3D0 w=3D0 time=3D1206 us)'
STAT #2 id=3D3 cnt=3D1 pid=3D2 pos=3D1 obj=3D3 op=3D'INDEX UNIQUE SCAN =
I_OBJ# (cr=3D2
r=3D0=20
w=3D0 time=3D41 us)'
STAT #2 id=3D4 cnt=3D0 pid=3D1 pos=3D2 obj=3D354 op=3D'INDEX UNIQUE SCAN =
I_NTAB2
(cr=3D2=20
r=3D0 w=3D0 time=3D245 us)'
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
PARSING IN CURSOR #2 len=3D116 dep=3D1 uid=3D0 oct=3D3 lid=3D0 =
tim=3D2284767571969=20
hv=3D431456802 ad=3D'b8dae190'
select=20
o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataobj
#,o.flags=20
from obj$ o where o.obj#=3D:1
END OF STMT
PARSE =
#2:c=3D0,e=3D133,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D2=
284767571962
BINDS #2:
  bind 0: dty=3D2 mxl=3D22(22) mal=3D00 scl=3D00 pre=3D00 oacflg=3D08 =
oacfl2=3D1
size=3D24=20
offset=3D0
    bfp=3Dffffffff7c864cd0 bln=3D22 avl=3D04 flg=3D05
    value=3D533312
EXEC =
#2:c=3D0,e=3D249,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D1,og=3D4,tim=3D2=
284767572541
FETCH =
#2:c=3D0,e=3D80,p=3D0,cr=3D3,cu=3D0,mis=3D0,r=3D1,dep=3D1,og=3D4,tim=3D22=
84767572687
WAIT #1: nam=3D'rdbms ipc reply' ela=3D 2006563 p1=3D5 p2=3D21474836 =
p3=3D0
WAIT #1: nam=3D'rdbms ipc reply' ela=3D 2001840 p1=3D5 p2=3D21474834 =
p3=3D0
WAIT #1: nam=3D'rdbms ipc reply' ela=3D 2001801 p1=3D5 p2=3D21474832 =
p3=3D0
WAIT #1: nam=3D'rdbms ipc reply' ela=3D 2001828 p1=3D5 p2=3D21474830 =
p3=3D0
WAIT #1: nam=3D'rdbms ipc reply' ela=3D 2001836 p1=3D5 p2=3D21474828 =
p3=3D0

and so on.

regards

Wolfgang Breitling
Centrex Consulting Corporation
www.centrexcc.com=20

----------------------------------------------------------------
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
-----------------------------------------------------------------
----------------------------------------------------------------
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: