Re: intermittent long "log file sync" waits
Date: Thu, 6 Feb 2020 23:43:22 -0500
Message-ID: <CAMHX9J+5Ysh_DiSohc_1ZqpKQiFmjbD+t+XoiPWML1BNABdQeQ_at_mail.gmail.com>
Since we don't see any FG metrics like *redo synch polls* and *redo synch poll writes* it looks like you're using the plain old post/wait mechanism with LGWR. This looks like a case of missed post to me.
As I understand this is not production, so you could use X$TRACE to dig deeper into POST/WAIT messages. X$TRACE is actually always enabled anyway (just not all events) so it should be safe for prod too, at least I haven't crashed anything with it yet.
You'd need to enable KST event 10005 at level 4 for just one test session and LGWR. I've used the Oracle PID below - 64 is the Oracle PID (not SPID) that my session is using. Would need to do the same for LGWR.
SQL> ALTER TRACING ENABLE "10005:4:64"; Tracing altered.
And since X$TRACE is a circular buffer, you'd need to quickly dump the X$TRACE buckets to disk or just CTAS it somewhere whenever you see a long log file sync. You could use some PL/SQL loop that polls ASH or V$SESSION and does such an INSERT-SELECT from X$TRACE whenever it sees anyone waiting for "log file sync" for longer than 1 sec. You could also make the X$TRACE buffers bigger to have a bit more time to react.
The output would give you a timeline of session wait events *and* POSTS sent and received. You can use the "relative_time_sec" column to see when the POSTs were actually sent by your FG and received by LGWR ... and vice versa.
SQL> _at_xt sid=509
relative_time_sec event file.c FUNCTION siddata
------------------- ------- -------------- ------------------------ ------- ------------------------------------------------------------------------------------------------------------------------------------ 634363269.049747 10005 ksl2.c_at_3349 kslwtbctx 509KSL WAIT BEG [SQL*Net message from client] 1952673792/0x74637000 1/0x1 0/0x0 wait_id=2764 seq_num=2766 snap_id=1
634363279.784638 10005 ksl2.c_at_3492 kslwtectx 509KSL WAIT END [SQL*Net message from client] 1952673792/0x74637000 1/0x1 0/0x0 wait_id=2764 seq_num=2766 snap_id=1
634363279.784641 10005 ksl2.c_at_3496 kslwtectx 509KSL WAIT END wait times (usecs) - snap=10734887, exc=10734887, tot=10734887
634363279.784850 10005 ksl2.c_at_19892 ksl_update_post_stats
509 *KSL
POST SENT postee=20 num=3 loc='ksa2.h LINE:292 ID:ksasnd' flags=0x0 id1=0
id2=0*
634363279.784983 10005 ksl2.c_at_3349 kslwtbctx 509KSL WAIT BEG [Disk file operations I/O] 8/0x8 0/0x0 8/0x8 wait_id=2765 seq_num=2767 snap_id=1
634363279.785058 10005 ksl2.c_at_3492 kslwtectx 509KSL WAIT END [Disk file operations I/O] 8/0x8 0/0x0 8/0x8 wait_id=2765 seq_num=2767 snap_id=1
634363279.785060 10005 ksl2.c_at_3496 kslwtectx 509KSL WAIT END wait times (usecs) - snap=77, exc=77, tot=77
634363279.785207 10005 ksl2.c_at_3349 kslwtbctx
509 *KSL
WAIT BEG [log file sync] 4172/0x104c 143746492/0x89165bc 0/0x0 wait_id=2766
seq_num=2768 snap_id=1*
634363279.785888 10005 ksl2.c_at_18157 ksliwat 509KSL FACILITY WAIT fac#=3 time_waited_usecs=678
634363279.785895 10005 ksl2.c_at_18276 ksliwat
509 *KSL
POST RCVD poster=22 num=8332 loc='ksl2.h LINE:4384 ID:kslpsr' id1=162 id2=0
name=EV type=0 fac#=3 posted=0x3 may_be_posted=1*
634363279.785904 10005 ksl2.c_at_3492 kslwtectx
509 *KSL
WAIT END [log file sync] 4172/0x104c 143746492/0x89165bc 0/0x0 wait_id=2766
seq_num=2768 snap_id=1*
634363279.785905 10005 ksl2.c_at_3496 kslwtectx 509 KSL WAIT END wait times (usecs) - snap=685, exc=685, tot=685 634363279.785948 10005 ksl2.c_at_3349 kslwtbctx 509KSL WAIT BEG [SQL*Net message to client] 1952673792/0x74637000 1/0x1 0/0x0 wait_id=2767 seq_num=2769 snap_id=1
634363279.785952 10005 ksl2.c_at_3492 kslwtectx 509KSL WAIT END [SQL*Net message to client] 1952673792/0x74637000 1/0x1 0/0x0 wait_id=2767 seq_num=2769 snap_id=1
634363279.785953 10005 ksl2.c_at_3496 kslwtectx 509 KSL WAIT END wait times (usecs) - snap=6, exc=6, tot=6 634363279.785964 10005 ksl2.c_at_3349 kslwtbctx 509KSL WAIT BEG [SQL*Net message from client] 1952673792/0x74637000 1/0x1 0/0x0 wait_id=2768 seq_num=2770 snap_id=1
The *KSL POST SENT postee=20* shows you the Oracle PID of LGWR in the above example. My FG session sent a wakeup message to LGWR.
The *KSL POST RCVD postee=22* shows that the "OK" reply came back from another process (Oracle PID 22). This was the LG00 log writer slave in my case. The LGnn slaves can do post-back to the foregrounds for scalability (so that LGWR itself wouldn't spend so much time in the semaphore operation system calls).
At the end of the day, this would still just confirm that LGWR misses a post for some reason, you'd still need to find which bug causes it.
This doesn't seem to be Exadata, right? LGWR and commit processing with Exafusion & Smart Fusion Block Transfer has gotten more complex (and faster), the GC layer doesn't have to wait for log file sync completion before shipping a modified block to remote instance, but commits on that remote instance still have to confirm that the log write on the original instance had completed. So there are additional potential synchronization/wait points in that configuration. This feature should be exadata-only, but maybe some artifacts from that implementation affect the non-exa config too.
One thing of interest, FG snapper output shows a short "IPC group service call" wait event right after a long log file sync ended and that's related to the Exafusion KSIPC layer.
P.S. For people wondering, I talk about X$TRACE and advanced wait event & post-wait topics in this hacking session: https://www.youtube.com/watch?v=mkmvZv58W6w
-- Tanel Poder https://tanelpoder.com/seminar On Thu, Feb 6, 2020 at 1:55 PM Chris Stephens <cstephens16_at_gmail.com> wrote: > At Sayan's excellent suggestion here is the full snapper output from > foreground sessions and lg* processes: > > https://gist.github.com/cs2018ncsa/e9b0d442247f1434ceef21124bef18c3 > > On Thu, Feb 6, 2020 at 10:17 AM Chris Stephens <cstephens16_at_gmail.com> > wrote: > >> resending w/ inline snapper foreground output of max "FG wakeup overhead >> per log file sync" time while i wait for moderator to approve previous >> email w/ attachments of lgwr and foreground snapper output from problem >> interval occurring later in the evening last night. like i said in previous >> email, i'm not exactly sure how to zero in on issue but "FG wakeup.." times >> look extremely suspicious to me. >> >> FG: >> >> *** 2020-02-05T17:44:15.593425-06:00 >> 1474 _at_3, GEN3_MGOWE, WAIT, SQL*Net message from client >> , 12000000, 953.02ms, 95.3%, [WWWWWWWWWW], >> 0, 0, 12s average wait >> 1717 _at_3, GEN3_MGOWE, STAT, Requests to/from client >> , 54, 4.29, , , >> , , .96 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, opened cursors cumulative >> , 22, 1.75, , , >> , , .7 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, user commits >> , 5, .4, , , >> , , .11 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, user calls >> , 74, 5.88, , , >> , , 1.3 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, recursive calls >> , 21, 1.67, , , >> , , 251.62us recursive CPU per recursive call >> 1717 _at_3, GEN3_MGOWE, STAT, session logical reads >> , 167, 13.26, , , >> , , 20.64k total buffer visits >> 1717 _at_3, GEN3_MGOWE, STAT, CPU used when call started >> , 2, .16, , , >> , , 760ms total CPU used when call started >> 1717 _at_3, GEN3_MGOWE, STAT, CPU used by this session >> , 2, .16, , , >> , , 760ms total CPU used by this session >> 1717 _at_3, GEN3_MGOWE, STAT, DB time >> , 1016, 80.69, , , >> , , 12.8 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, non-idle wait time >> , 1234, 98, , , >> , , 12.93 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, non-idle wait count >> , 194, 15.41, , , >> , , 3.72 per execution >> 1717 _at_3, GEN3_MGOWE, STAT, process last non-idle time >> , 10, .79, , , >> , , 1.33M per execution >> 1717 _at_3, GEN3_MGOWE, STAT, messages sent >> , 6, .48, , , >> , , .14 per execution >> >>> >>>>>>>> -- http://www.freelists.org/webpage/oracle-lReceived on Fri Feb 07 2020 - 05:43:22 CET