Comments:
1) First, looks like you're using all the right tools for systematic
troubleshooting ;-)
2) As "log file sync" is not directly an I/O wait event (IO happens
indirectly under the hood), but "wait for LGWR to ACK/increment redo
persisting position" then there may be multiple reasons for delays. I'm
repeating some of what others have said here too:
- LGWR could be waiting for remote ACK (synchronous data guard) - that
should show up as a LNS* wait or something like that though
- Process slowness due to CPU overload/scheduling latency or swapping (in
both cases, LGWR may do its work fast, but it takes a while for the
foreground process to wake up and end the wait event - you could check if
there are any reports regarding switching LGWR mode in alert.log around
that time)
- Bug/missed post due to switching between LGWR progress polling vs.
waiting for LGWR post
- ASM instance communication issues (ASM communication can be on the
critical path when creating/changing files on ASM and even for reading,
when the ASM metadata cache in your local instance doesn't have what it
needs)
- So, the physical redo log file disk write is not necessarily the
biggest contributor to the log file sync wait
3) You'll need to measure what LGWR itself was doing during the problem time
- Since you're on 19c (12c or later) the LGWR has slaves too and they may
be doing most of the work
- You'll need to look into both the LGWR process and any other LG* ones
too
- Since you have (Oracle) Snapper running already and writing to trace
you should have the data already
- The *lgwr* in the following @snapper ash,stats,trace 10 999999 lgwr
syntax includes LGWR slaves too
- As LGWR slaves have their own sessions (and SIDs), you should run
ashtop etc and report if there's any BLOCKING_SESSION value listed for LGWR
and slaves
- If LGWR and the slaves were listed *idle* during the problem time
(while others waited for log file sync event at the same time) *and if *there
was no huge OS level CPU/memory shortage at the time, this looks like a
background <-> foreground communication problem.
- This (and any potential ASM issues) could probably be troubleshooted
via KST tracing, KSR channels and X$TRACE that could help here (some of it
is enabled by default ( Like I showed in a previous hacking session:
https://www.youtube.com/watch?v=mkmvZv58W6w ;)
4) Paste the full *Snapper* output (of one time snapshot from the problem
time) here if you can - we'll be able to see what the slaves were doing
- You'd need to include not only LGWR SID but also any LG* slave SIDs too
- Also we'll see better LGWR delay metrics from V$SESSTAT that go beyond
just wait events
- Thinking of metrics like these - snapper already handles them (if you
look into the rightmost column)
- *redo synch time overhead (usec)* - "FG wakeup overhead per log file
sync"
- *redo write time* - accounting end to end redo write time (not just
the log file parallel write syscall) "per redo write"
5) Regarding the *ASH wait chains* error on 19c - I'm aware of this but
forgot to look into it
- It has (probably) something to do with GV$ views (or PX slaves used
for PDB V$ queries) and possibly the connect by I'm using
- Does it work in the CDB (if multitenant)?
- Does it work with lower optimizer features enabled?
- As we are already manually looking into what LGWR and its slaves are
doing, there's no need for the wait chains script here
6) Linux Process Snapper - pSnapper
- If you want to see the full "wait" states of Linux processes/threads,
use the* -a *option.
- It's somewhat like always showing "idle" threads too
- But for linux apps it's harder to determine what's idle and what's
some network RPC wait, so I currently just do what Linux "load" metric does
- I just shows threads in Runnable and Disk/Uninterruptible sleep states
by default (-a shows all states, including Sleep and kernel-Idle threads
etc)
- So the Linux pSnapper "idle" means a somewhat different thing than
Oracle "idle" - say LGWR was waiting for a Data Guard ACK, that should not
be shown as Idle in Oracle, but at the Linux process level it's "just some
network socket wait" and you'd need to use *-a* option to show all of them
7) Were LGWR/LG* processes mostly idle during the problem time?
- As I kept reading the thread, it looks like ASH reported LGWR being
mostly idle during the problem time
- This is not exactly the same pattern, but I've seen cases in the past
where everyone's waiting for LGWR and LGWR doesn't seem to be busy and
doesn't show any significant waits
- It turned out that LGWR was actually waiting for CKPT to make
progress, but it wasn't synchronously waiting, but just going to sleep and
"checking again later" in a loop
- I wrote about this here:
https://blog.tanelpoder.com/posts/log-file-switch-checkpoint-incomplete-and-lgwr-waiting-for-checkpoint-progress/
- So it may still make sense to check what LGWR/LG* processes are doing
even if they don't seem to be active much (like do you see an occasional
controlfile read wait by LGWR etc)
- SQL*Trace would capture all activity of LGWR, but may slow things down
further, so you could also sample & spool V$SESSION_WAIT_HISTORY (that
keeps a log of last 10 waits of every session in memory)
Incidentally I'm doing another hacking session tomorrow (Thursday 30 Jan @
12pm ET) about complex Oracle performance problems that span multiple
layers and have multiple moving parts. I can add some LGWR troubleshooting
magic in the end of that (here goes my plan to fit the session in 1.5h
again!). I'll post the details in my blog in a few minutes.
--
Tanel Poder
https://blog.tanelpoder.com/seminar
On Tue, Jan 28, 2020 at 2:22 PM Chris Stephens <cstephens16@xxxxxxxxx>
wrote:
doesn't look like any ash data for lgwr:
SQL> @ashtop session_id,blocking_session,event2 1=1 "TIMESTAMP'2020-01-27
15:50:48'" "TIMESTAMP'2020-01-27 15:52:40'"
TOTALSECONDS AAS %This SESSION_ID BLOCKING_SESSION
EVENT2 FIRST_SEEN LAST_SEEN
DIST_SQLEXEC_SEEN
_______________ ______ __________ _____________ ___________________
_____________________ ______________________ ______________________
____________________
81 0.7 82% | 1713 1710 log
file sync 2020-01-27 15:50:54 2020-01-27 15:52:14
1
5 0 5% | 1221 ON CPU
2020-01-27 15:50:59 2020-01-27 15:52:14
1
3 0 3% | 246 ON CPU
2020-01-27 15:51:00 2020-01-27 15:52:00
1
3 0 3% | 1713 ON CPU
2020-01-27 15:50:51 2020-01-27 15:52:27
2
1 0 1% | 123 ON CPU
2020-01-27 15:51:35 2020-01-27 15:51:35
1
1 0 1% | 127 ON CPU
2020-01-27 15:51:50 2020-01-27 15:51:50
1
1 0 1% | 252 2321 latch
free 2020-01-27 15:52:28 2020-01-27 15:52:28
1
1 0 1% | 978 ges
remote message 2020-01-27 15:50:48 2020-01-27 15:50:48
1
1 0 1% | 983 latch
free 2020-01-27 15:52:28 2020-01-27 15:52:28
1
1 0 1% | 1713
library cache lock 2020-01-27 15:50:48 2020-01-27 15:50:48
1
1 0 1% | 1831 ON CPU
2020-01-27 15:50:49 2020-01-27 15:50:49
1
11 rows selected.
SQL> @ashtop session_id,blocking_session,event2 session_id=1710
"TIMESTAMP'2020-01-27 15:50:48'" "TIMESTAMP'2020-01-27 15:52:40'"
no rows selected
On Tue, Jan 28, 2020 at 1:09 PM Noveljic Nenad <
nenad.noveljic@xxxxxxxxxxxx> wrote:
You’re using v0.2, but v0.6 should be the latest version. 0.2 wouldn’t
show idle blockers.
I looked at the ashtop output once again. Strange that lgwr processes nor
any other bg processes show up significantly there. The question is, what
was lgwr doing while the fg processes were waiting on him.
