Re: intermittent long "log file sync" waits

  • From: Tanel Poder <tanel@xxxxxxxxxxxxxx>
  • To: Tanel Poder <tanel@xxxxxxxxxxxxxx>
  • Date: Wed, 5 Feb 2020 17:47:14 -0500

Oh, forgot to add that the reason why you don't see much "redo write"
metric activity in LGWR's session is that when LGnn slaves kick in, they'll
be doing all the disk IO and LGWR is just a master/coordinator. When
running snapper on all of them (or look into X$TRACE post/wakeup activity),
you'd see the different roles they have. Starting from 12c one would always
need to look into LGWR and all its slaves when troubleshooting, otherwise
you risk missing critical clues.

--
Tanel Poder
https://tanelpoder.com/seminar

On Wed, Feb 5, 2020 at 5:44 PM Tanel Poder <tanel@xxxxxxxxxxxxxx> wrote:

Man, I wrote an answer with 4 bullet points and them managed to
"select+all" and delete the text just before hitting send.

The short version (possibly with typos):

*1) *Would still like to see the full Snapper output of LGWR *and* LG*
processes during the problem time

*2) *The *redo write* metrics in v$sesstat are about LGWR writes, not
foreground commit latency experience

*3) *For understanding end to end foreground commit latency, you'd need
to look into *redo synch* metrics. 18c has over 70 redo synch metrics,
but some years ago (I think when 12c was introduced) I added one metric of
interest to Snapper: *redo synch time overhead (usec)*.

I actually divide it by *redo synch writes*, giving a derived metric that
I call *FG wakeup overhead per log file sync* in Snapper.

You'd need to run this on some of the foreground sessions experiencing the
problem, not LGWR. If the problem is system-wide and lasts for long enough,
you may be able to see something in AWR/v$sysstat too, although the various
averaging may hide detail there.

*4) *Cursor #0 is shown when the client is making "cursorless" top-level
database calls like OCICommit() in OCI or conn.commit() in JDBC, instead of
parsing and executing a SQL statement with text "commit" in it. The
top_level_call_name in ASH or OPI trace event 10051 would show "COMMIT" as
the database call instead of V8 Bundled Exec
<https://tanelpoder.com/2011/08/23/v8-bundled-exec-call-and-oracle-program-interface-opi-calls/>
.

SQL> @tlc commit
Display top-level call names matching %commit% (Oracle 11.2+)

TOP_LEVEL_CALL# TOP_LEVEL_CALL_NAME
--------------- ---------------------------------------------
             12 COMMIT ON
             13 COMMIT OFF
             14 COMMIT
             89 XA XA Commit
            104 Transaction Commit/Rollback
            117 Commit Remote Sites
            127 Commit Remote Sites >= V813

--
Tanel Poder
https://tanelpoder.com/seminar


On Wed, Feb 5, 2020 at 5:32 PM Tanel Poder <tanel@xxxxxxxxxxxxxx> wrote:



Other related posts: