Re: Very high 'log file sync' wait time with no 'log file parallel write' wait time

mccmx_at_hotmail.com wrote:
> I just see thousands of EXEC calls for COMMIT, each with an associated
> 'log file sync' wait:
>
> PARSING IN CURSOR #9 len=6 dep=1 uid=21 oct=44 lid=21 tim=276327492
> hv=255718823 ad='0'
> COMMIT
> END OF STMT
> EXEC #9:c=0,e=2140,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276327489
> WAIT #9: nam='log file sync' ela= 1848 buffer#=3637 p2=0 p3=0 obj#=0
> tim=276329947
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1983,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276330067
> WAIT #9: nam='log file sync' ela= 1708 buffer#=3639 p2=0 p3=0 obj#=0
> tim=276331899
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1848,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276332033
> WAIT #1: nam='SQL*Net more data from client' ela= 27 driver
> id=1111838976 #bytes=2 p3=0 obj#=0 tim=276332165
> WAIT #9: nam='log file sync' ela= 1883 buffer#=3641 p2=0 p3=0 obj#=0
> tim=276334144
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=2011,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276334265
> WAIT #9: nam='log file sync' ela= 1789 buffer#=3643 p2=0 p3=0 obj#=0
> tim=276336184
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=2174,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276336561
> WAIT #9: nam='log file sync' ela= 1767 buffer#=3645 p2=0 p3=0 obj#=0
> tim=276338452
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1896,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276338574
> WAIT #9: nam='log file sync' ela= 1766 buffer#=3647 p2=0 p3=0 obj#=0
> tim=276340465
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1896,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276340589
> WAIT #9: nam='log file sync' ela= 1981 buffer#=3649 p2=0 p3=0 obj#=0
> tim=276342693
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=2109,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276342814
> WAIT #9: nam='log file sync' ela= 1646 buffer#=3651 p2=0 p3=0 obj#=0
> tim=276344584
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1776,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276344707
> WAIT #9: nam='log file sync' ela= 1696 buffer#=3653 p2=0 p3=0 obj#=0
> tim=276346527
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1822,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276346647
> WAIT #9: nam='log file sync' ela= 1740 buffer#=3655 p2=0 p3=0 obj#=0
> tim=276348508
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1870,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276348632
> WAIT #9: nam='log file sync' ela= 1781 buffer#=3657 p2=0 p3=0 obj#=0
> tim=276350538
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1992,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276350741
> WAIT #1: nam='SQL*Net more data from client' ela= 19 driver
> id=1111838976 #bytes=4 p3=0 obj#=0 tim=276351195
> WAIT #9: nam='log file sync' ela= 1720 buffer#=3659 p2=0 p3=0 obj#=0
> tim=276353054
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1862,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276353185
> WAIT #9: nam='log file sync' ela= 1800 buffer#=3661 p2=0 p3=0 obj#=0
> tim=276355113
> XCTEND rlbk=0, rd_only=1
> EXEC #9:c=0,e=1927,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=276355232
> WAIT #9: nam='log file sync' ela= 1968 buffer#=3663 p2=0 p3=0 obj#=0
> tim=276357322
> XCTEND rlbk=0, rd_only=1
>
> Matt

Matt,

One item of interest is that all of the transaction end markers (commits) are read only (XCTEND rlbk=0, rd_only=1). This is the case when a commit is issued but involves no work. You can reproduce this by tracing a session in which you update a row (even to its current value), and then issue two commits. The first commit will show rd_only = 0, while the second will show rd_only = 1.

This explains why you are only seeing the updates in the table every 10,000 rows. The previous 9,999 commits are read only, i.e., involve no "real" change.

This may also explain why they are showing up under the recursive section of the trace. It seems that I read somewhere once before that you can see this behaviour with LMT's, as it represents the "internal" commits performed by the software for space management operations, as redo is involved for these operations. No dictionary tables are updated, but a "commit" is performed when the bitmap is changed. I cannot find the source right now, and maybe someone else knows differently, but I would be curious to see if you can reproduce it when the space is already allocated, i.e., load the table, delete, and then reload so all the extents are already allocated. I realize that is a lot of work for something that I cannot say for certainty is the problem, but the fact they are all read only leads me in at least some "under the hood" recursive direction.

HTH, Steve Received on Tue Nov 28 2006 - 10:12:53 CST