RSS Feed

Method R Discussion Group

I am interested to know why there are wait events attributed to cursor #0 in a trace file that I have collected (see below : "log file sync" event - costing 1/3 second!).  I am using Oracle v.8.1.7.3.0 and multi master replication is configured: hence the DML against SYSTEM.DEF$_AQCALL.

=====================
PARSING IN CURSOR #1 len=120 dep=0 uid=107 oct=6 lid=107 tim=315078757 hv=2120732061 ad='b8060a4'
UPDATE "SRV"."SRV_PULSE" SET "LASTPULSE"=:V00001,"STATUS"=0 WHERE "LASTPULSE"=:V00003 AND "STATUS"=1 AND "ROWID"=:V00005
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=315078757
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #5:c=0,e=0,p=0,cr=0,cu=6,mis=0,r=1,dep=1,og=4,tim=315078757
EXEC #1:c=0,e=0,p=0,cr=1,cu=9,mis=0,r=1,dep=0,og=4,tim=315078757
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
STAT #1 id=1 cnt=1 pid=0 pos=0 obj=0 op='UPDATE SRV_PULSE '
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=45870 op='TABLE ACCESS BY USER ROWID SRV_PULSE '
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=0
=====================
PARSING IN CURSOR #1 len=69 dep=1 uid=0 oct=6 lid=0 tim=315078757 hv=254026706 ad='ae7d288'
update SYSTEM.DEF$_AQCALL  set dscn = :1, cscn = :2  where rowid = :3
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=315078757
EXEC #1:c=0,e=0,p=0,cr=1,cu=5,mis=0,r=1,dep=1,og=4,tim=315078757
STAT #1 id=1 cnt=1 pid=0 pos=0 obj=0 op='UPDATE DEF$_AQCALL '
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=2563 op='TABLE ACCESS BY USER ROWID DEF$_AQCALL '
WAIT #0: nam='log file sync' ela= 33 p1=46 p2=0 p3=0
WAIT #0: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #0: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #0: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #0: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
=====================

I didn't stress that it was the meaning of #0 that I was interested in (because all cursors normally seem to start at #1).  There is plenty of material available to me regarding the causes of "log file sync". However, I can't tell whether the user process or a background process is causing this particular wait event to occur.

Any help gratefully received.

It's the user process. (Everything in the 10046 trace data is motivated by actions of the user process.)

The cursor id number 0 is what the Oracle kernel uses to aggregate system calls (like the code path behind the Oracle 'log file sync' name) that are not attributable to an explicit application-managed cursor.

So cursor #0 often ends up collecting a lot of 'log file sync' and 'SQL*Net message from client' OS calls executed on behalf of COMMIT processing.

The Hotsos Profiler automatically takes care of all the complexity associated with cursor #0 processing.

Thanks for your reply, Cary. The Hotsos P5 Profiler assisted in the identification of this wait event being significant. However, under section 4.3. "Statement Contributors to «log file sync»" the contributing statement cannot be identified: "[no hv] <no text for statement>".

I was wanting to know which statement was being affected by the wait: i.e. the "user" SQL (dep=0) or the recursive SQL (dep=1) but I guess that it doesn't matter in this particular case: it's the frequency of COMMITs that is taking place (perhaps system-wide) that matters, right?