Re: Queries which causes log file sync
- From: Tanel Poder <tanel@xxxxxxxxxx>
- To: exriscer@xxxxxxxxx
- Date: Fri, 15 Oct 2010 18:03:32 +0300
XCTEND followed by log file sync, some dblink activity and another log file
sync seems like two phase commit.
The *rd_only=1* says that there was no transaction to commit.
So, something is committing there.
If you see an XCTEND in trace file without a corresponding COMMIT SQL cursor
execution, then it was a cursor-less commit called directly via OPI (
OCICommit() ).
That would explain also why these waits are attributed to cursor #21 as the
commit op itself was cursorless (sometimes Oracle shows cursor #0 in such
cases, but maybe with OPI commits its different (or a bug, Cary probably
knows).
Perhaps somewhere earlier in the trace a SET TRANSACTION READ ONLY was used
or more likely, that session did reference some remote object via a dblink
earlier and now the commit was issued in the app.
--
Tanel Poder
New virtual conference and online seminars!
http://tech.e2sn.com/virtual-conferences
http://tech.e2sn.com/oracle-training-seminars
On Fri, Oct 15, 2010 at 3:37 PM, LS Cheng <exriscer@xxxxxxxxx> wrote:
> Hi
>
> I am reviewing a database which is suffering some high log file sync
> contention. When I 10046 traced an user I see some ALTER o queries which
> waits on dblink and log file sync as follows:
>
> PARSING IN CURSOR #33 len=46 dep=0 uid=39 oct=42 lid=39
> tim=1256972268965166 hv=258095734 ad='0'
> ALTER SESSION SET NLS_DATE_FORMAT='yyyy-mm-dd'
> END OF STMT
> PARSE #33:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1256972268965164
> WAIT #33: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972268965356
> WAIT #33: nam='SQL*Net message from dblink' ela= 5273 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972268970653
> WAIT #33: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972268970690
> WAIT #33: nam='SQL*Net message from dblink' ela= 4327 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972268975041
> EXEC
> #33:c=1000,e=9925,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,tim=1256972268975131
> XCTEND rlbk=0, rd_only=1
> WAIT #33: nam='log file sync' ela= 36035 buffer#=8663 p2=0 p3=0 obj#=32461
> tim=1256972269011312
> WAIT #33: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269011418
> WAIT #33: nam='SQL*Net message from dblink' ela= 95908 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269107351
> WAIT #33: nam='SQL*Net message to dblink' ela= 0 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269107372
> WAIT #33: nam='SQL*Net message from dblink' ela= 10200 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269117586
> WAIT #33: nam='log file sync' ela= 16126 buffer#=8665 p2=0 p3=0 obj#=32461
> tim=1256972269133898
> WAIT #33: nam='SQL*Net message to client' ela= 1 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269134102
> WAIT #33: nam='SQL*Net message from client' ela= 1650 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269135779
>
> PARSE #21:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1256972269488791
> WAIT #21: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269488959
> WAIT #21: nam='SQL*Net message from dblink' ela= 349 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269489332
> WAIT #21: nam='SQL*Net message to dblink' ela= 0 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269489354
> WAIT #21: nam='SQL*Net message from dblink' ela= 485 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269489859
> EXEC #21:c=0,e=1122,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,tim=1256972269489927
> XCTEND rlbk=0, rd_only=1
> WAIT #21: nam='log file sync' ela= 5347 buffer#=8785 p2=0 p3=0 obj#=32461
> tim=1256972269495375
> WAIT #21: nam='SQL*Net message to dblink' ela= 0 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269495405
> WAIT #21: nam='SQL*Net message from dblink' ela= 23623 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269519047
> WAIT #21: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269519092
> WAIT #21: nam='SQL*Net message from dblink' ela= 3462 driver id=1413697536
> #bytes=1 p3=0 obj#=32461 tim=1256972269522573
> WAIT #21: nam='log file sync' ela= 7743 buffer#=8787 p2=0 p3=0 obj#=32461
> tim=1256972269530450
> WAIT #21: nam='SQL*Net message to client' ela= 1 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269530571
> WAIT #21: nam='SQL*Net message from client' ela= 430 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269531029
>
> When I searched backwards to find the cursor #21 I found this:
>
> PARSING IN CURSOR #21 len=429 dep=0 uid=39 oct=3 lid=39
> tim=1256972269368544 hv=751543218 ad='2a9647e0'
> select ident_code, patient, state, entered_date, entered_hour, servingr,
> motaten, procede, documentation URG_EPISODE.SITE SITE from urg_episode where
> ident_code = 300722444
> END OF STMT
> PARSE
> #21:c=1999,e=1931,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=1256972269368541
> BINDS #21:
> EXEC #21:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1256972269368627
> WAIT #21: nam='SQL*Net message to client' ela= 1 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269368660
> WAIT #21: nam='SQL*Net message from client' ela= 233 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269368993
> WAIT #21: nam='SQL*Net message to client' ela= 0 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269369045
> FETCH #21:c=0,e=56,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=1256972269369071
> WAIT #21: nam='SQL*Net message from client' ela= 535 driver id=1952673792
> #bytes=1 p3=0 obj#=32461 tim=1256972269369648
> STAT #21 id=1 cnt=1 pid=0 pos=1 obj=30108 op='TABLE ACCESS BY INDEX ROWID
> URG_EPISODIO (cr=4 pr=0 pw=0 time=25 us)'
> STAT #21 id=2 cnt=1 pid=1 pos=1 obj=31516 op='INDEX UNIQUE SCAN
> IURGEPISODIO_PK (cr=3 pr=0 pw=0 time=16 us)'
>
> So this puzzles me, why an ALTER SESSION and query waits for dblink and log
> file sync (there is no remote tables involved).
>
> Also whenever there is a log file sync wait there are also SQL*Net message
> to dblink and SQL*Net message from dblink waits, it is true that there is
> commit going on as well (XCTEND rlbk=0, rd_only=1) but what is dblink
> doing here?
>
>
> Any lights?
>
> TIA
>
> --
> LSC
>
>
>
>
Other related posts:
