Re: intermittent long "log file sync" waits

From: Tanel Poder <tanel_at_tanelpoder.com>
Date: Wed, 5 Feb 2020 17:47:14 -0500
Message-ID: <CAMHX9J+c6J8nDCygGkNVOCu1pR8b3MpH5LxEH3jTxGmGkpOB5w_at_mail.gmail.com>



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_at_tanelpoder.com> 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> _at_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_at_tanelpoder.com> wrote:
>
>>
>>>>>
-- http://www.freelists.org/webpage/oracle-l
Received on Wed Feb 05 2020 - 23:47:14 CET

Original text of this message