On Fri, 13 Oct 2006, Christian Antognini wrote:
> In your trace file log file sync events are scattered over the whole
> trace file?
hi - no, they are in large blocks through the file. For example there
will be sort of like this (values removed to keep the boss happy):
BINDS #13:
bind 0: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01
oacfl2=c000000000000000 size=176 offset=0
bfp=800003ff7405ff38 bln=32 avl=10 flg=05
bind 1: dty=2 mxl=78(22) mal=00 scl=00 pre=00 oacflg=01
oacfl2=c000000000000000 size=0 offset=32
bfp=800003ff7405ff58 bln=78 avl=02 flg=01
bind 2: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01
oacfl2=c000000000000000 size=0 offset=112
bfp=800003ff7405ffa8 bln=32 avl=05 flg=01
bind 3: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01
oacfl2=c000000000000000 size=0 offset=144
bfp=800003ff7405ffc8 bln=32 avl=11 flg=01
WAIT #13: nam='db file sequential read' ela= 96 p1=8 p2=143924 p3=1
WAIT #13: nam='log file sync' ela= 6337 p1=3191 p2=0 p3=0
WAIT #13: nam='log file sync' ela= 2101 p1=3386 p2=0 p3=0
WAIT #13: nam='log file sync' ela= 1858 p1=3387 p2=0 p3=0
WAIT #13: nam='log file sync' ela= 955 p1=3388 p2=0 p3=0
... 100+ lines of log file sync
WAIT #13: nam='db file sequential read' ela= 76 p1=79 p2=69671 p3=1
WAIT #13: nam='db file sequential read' ela= 46 p1=78 p2=69819 p3=1
WAIT #13: nam='db file sequential read' ela= 41 p1=78 p2=69823 p3=1
WAIT #13: nam='log file sync' ela= 863 p1=3506 p2=0 p3=0
WAIT #13: nam='db file sequential read' ela= 42 p1=78 p2=69827 p3=1
WAIT #13: nam='db file sequential read' ela= 38 p1=78 p2=69831 p3=1
WAIT #13: nam='db file sequential read' ela= 36 p1=79 p2=69675 p3=1
WAIT #13: nam='db file sequential read' ela= 38 p1=79 p2=69679 p3=1
... a log file sync every 10 db file sequential read then
EXEC
#13:c=140000,e=264079,p=76,cr=8750,cu=4739,mis=0,r=56,dep=0,og=4,tim=22023951788104
WAIT #13: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #13: nam='SQL*Net message from client' ela= 261 p1=1413697536 p2=1
p3=0
The behavior changes but overall it is in this form:
new bind values given (BINDS #13)
a brief sequential read (1 block p3=1)
100+ lines of log file sync
some db file sequential read of 1 block (5-10 lines)
a log file sync
some more db file sequential read of 1 block (5-10 lines)
a log file sync
... repeat previous 5 lines a few dozen times ...
an EXEC
send some sort of acknowledgement to client (p2=1) ?
receive some sort of acknowledgement from client (p2=1) ?
This happens nearly 10,000 times.
I did a grep on the tracefile:
Count of BINDS #13 - 9974
Count of 'db file sequential read' - 56882
Count of 'log file sync' - 1564723
Count of 'SQL*Net message to client' - 9978
So I suppose at this point the log file sync may be a product of
log_buffer being too large or too small. I have tried large values of
5,000,000 and as small as 320,000. I will try lowering it to 160,000 and
re-test.
Any advice or opinions are very welcome... Thanks
--
//www.freelists.org/webpage/oracle-l
