Re: intermittent long "log file sync" waits

unfortunately, ash_wait_chains.sql doesn't work on 19.3 but here is ashtop showing foreground process blocked on lgwr (1710):

SQL> _at_ashtop inst_id,username,blocking_session,blocking_inst_id,event2 1=1 "TIMESTAMP'2020-01-27 15:50:48'" "TIMESTAMP'2020-01-27 15:52:40'"

   TOTALSECONDS    AAS      %This    INST_ID         USERNAME
 BLOCKING_SESSION    BLOCKING_INST_ID                EVENT2
FIRST_SEEN              LAST_SEEN    DIST_SQLEXEC_SEEN
_______________ ______ __________ __________ ________________
___________________ ___________________ _____________________
______________________ ______________________ ____________________
             81    0.7   82% |             2 GEN3_MGOWER_3
  1710                   2 log file sync         2020-01-27 15:50:54
 2020-01-27 15:52:14                       1
              9    0.1    9% |             1 SYS
                           ON CPU                2020-01-27 15:50:49
 2020-01-27 15:52:14                       1
              3      0    3% |             2 GEN3_MGOWER_3
                           ON CPU                2020-01-27 15:50:51
 2020-01-27 15:52:27                       2
              2      0    2% |             2 SYS
                           ON CPU                2020-01-27 15:51:35
 2020-01-27 15:51:40                       1
              1      0    1% |             2 GEN3_MGOWER_3
                           library cache lock    2020-01-27 15:50:48
 2020-01-27 15:50:48                       1
              1      0    1% |             2 SYS
  2321                   2 latch free            2020-01-27 15:52:28
 2020-01-27 15:52:28                       1
              1      0    1% |             2 SYS
                           ges remote message    2020-01-27 15:50:48
 2020-01-27 15:50:48                       1
              1      0    1% |             2 SYS
                           latch free            2020-01-27 15:52:28
 2020-01-27 15:52:28                       1

   NAME    DESCRIPTION     SID    OPID     SPID               PADDR
      SADDR
_______ ______________ _______ _______ ________ ___________________
___________________
LGWR    Redo etc.         1710      34 26552    00000001E8718860

> Hi Chris,
>
>
>
> log file sync measures much more than IO.
>
>
>
> First of all, I’d run Tanel’s ash_wait_chains (
> https://github.com/tanelpoder/tpt-oracle/blob/master/ash/ash_wait_chains.sql
> ), because if often points straightly to the root cause .
>
>
>
> Here’s is a usage example, when intermittent log file sync waits where
> caused by slow control file writes:
> https://nenadnoveljic.com/blog/bad-commit-performance-control-file-writes/
> .
>
>
>
> Best regards,
>
>
> Nenad
>
>
>
>
>
>
>
> *From:* oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> *On
> Behalf Of *Chris Stephens
> *Sent:* Dienstag, 28. Januar 2020 17:09
> *To:* oracle-l <Oracle-L_at_freelists.org>
> *Subject:* intermittent long "log file sync" waits
>
>
>
> 3-node Oracle 19.3 RAC
>
> Centos 7
>
>
>
> We have a SQLAlchemy/Python based application workload that is running the
> exact same steps with widely varying response times which appear to be
> related to varying "log file sync" wait times.
>
>
>
> Here is a profile of a "fast" run:
>
>
>
> CALL-NAME DURATION % CALLS MEAN
> MIN MAX
> ------------------------------ --------- ------ ------ --------
> -------- ---------
> SQL*Net message from client 53.197782 91.8% 10,092 0.005271
> 0.000177 28.568493
> EXEC 3.759177 6.5% 9,816 0.000383
> 0.000000 0.239592
> row cache lock 0.233153 0.4% 541 0.000431
> 0.000113 0.000941
> PARSE 0.140399 0.2% 4,867 0.000029
> 0.000000 0.006620
> DLM cross inst call completion 0.137330 0.2% 956 0.000144
> 0.000004 0.000505
> library cache lock 0.100171 0.2% 215 0.000466
> 0.000151 0.002133
> library cache pin 0.079729 0.1% 216 0.000369
> 0.000056 0.000710
> FETCH 0.058253 0.1% 1,062 0.000055
> 0.000000 0.004148
> log file sync 0.048217 0.1% 149 0.000324
> 0.000259 0.000505
> CLOSE 0.045416 0.1% 4,929 0.000009
> 0.000000 0.000073
> 20 others 0.135624 0.2% 11,854 0.000011
> 0.000000 0.001700
> ------------------------------ --------- ------ ------ --------
> -------- ---------
> TOTAL (30) 57.935251 100.0% 44,697 0.001296
> 0.000000 28.568493
>
>
>
> Here is a profile of a "slow" run:
>
>
>
> CALL-NAME DURATION % CALLS MEAN
> MIN MAX
> ------------------------------ ---------- ------ ------ --------
> -------- ----------
> SQL*Net message from client 131.186118 61.0% 10,092 0.012999
> 0.000212 106.789360
> log file sync 79.291166 36.8% 150 0.528608
> 0.000264 2.986575
> EXEC 3.728402 1.7% 9,816 0.000380
> 0.000000 0.221403
> row cache lock 0.248868 0.1% 542 0.000459
> 0.000111 0.001036
> PARSE 0.164267 0.1% 4,867 0.000034
> 0.000000 0.004652
> DLM cross inst call completion 0.146981 0.1% 957 0.000154
> 0.000005 0.001188
> library cache lock 0.104354 0.0% 218 0.000479
> 0.000160 0.000728
> library cache pin 0.082504 0.0% 202 0.000408
> 0.000157 0.000672
> FETCH 0.056687 0.0% 1,062 0.000053
> 0.000000 0.003969
> CLOSE 0.043590 0.0% 4,929 0.000009
> 0.000000 0.000180
> 20 others 0.142044 0.1% 11,866 0.000012
> 0.000000 0.001792
> ------------------------------ ---------- ------ ------ --------
> -------- ----------
> TOTAL (30) 215.194981 100.0% 44,701 0.004814
> 0.000000 106.789360
>
>
>
> looking at even histogram for that event:
>
>
>
> SQL> _at_evh "log file sync"
> EVH_EVENT EVH_WAIT_TIME_MILLI WAIT_COUNT EVH_EST_TIME
> LAST_UPDATE_TIME
> ________________ ______________________ _____________ _______________
> ______________________________________
> log file sync < 1 200051 100.026
> 27-JAN-20 11.39.57.344734 PM -06:00
> log file sync < 2 165 0.248
> 28-JAN-20 12.18.10.429089 AM -06:00
> log file sync < 4 150 0.45
> 27-JAN-20 11.18.31.158102 PM -06:00
> log file sync < 8 199 1.194
> 27-JAN-20 11.19.14.209947 PM -06:00
> log file sync < 16 253 3.036
> 28-JAN-20 08.03.17.851328 AM -06:00
> log file sync < 32 472 11.328
> 27-JAN-20 11.20.22.746033 PM -06:00
> log file sync < 64 728 34.944
> 28-JAN-20 01.13.37.364541 AM -06:00
> log file sync < 128 691 66.336
> 27-JAN-20 11.31.37.400504 PM -06:00
> log file sync < 256 414 79.488
> 28-JAN-20 12.18.10.423987 AM -06:00
> log file sync < 512 405 155.52
> 28-JAN-20 03.27.50.540383 AM -06:00
> log file sync < 1024 459 352.512
> 27-JAN-20 11.35.14.378363 PM -06:00
> log file sync < 2048 482 740.352
> 28-JAN-20 01.18.20.556248 AM -06:00
> log file sync < 4096 576 1769.472
> 27-JAN-20 11.21.05.084998 PM -06:00
> log file sync < 8192 89 546.816
> 27-JAN-20 11.57.36.436460 AM -06:00
> log file sync < 16384 60 737.28
> 25-JAN-20 07.48.31.460408 AM -06:00
> log file sync < 32768 39 958.464
> 27-JAN-20 11.59.09.869286 AM -06:00
> log file sync < 65536 27 1327.104
> 25-JAN-20 09.49.13.856563 AM -06:00
>
>
>
> The weird thing is that I don't see corresponding log I/O waits (awaits)
> in iostat output.
>
>
>
> I have a ticket open w/ oracle but does anyone have any suggestions to
> discover root cause and/or solution?
>
> ____________________________________________________
>
> Please consider the environment before printing this e-mail.
>
> Bitte denken Sie an die Umwelt, bevor Sie dieses E-Mail drucken.
>
>
> Important Notice
> This message is intended only for the individual named. It may contain
> confidential or privileged information. If you are not the named addressee
> you should in particular not disseminate, distribute, modify or copy this
> e-mail. Please notify the sender immediately by e-mail, if you have
> received this message by mistake and delete it from your system.
> Without prejudice to any contractual agreements between you and us which
> shall prevail in any case, we take it as your authorization to correspond
> with you by e-mail if you send us messages by e-mail. However, we reserve
> the right not to execute orders and instructions transmitted by e-mail at
> any time and without further explanation.
> E-mail transmission may not be secure or error-free as information could
> be intercepted, corrupted, lost, destroyed, arrive late or incomplete. Also
> processing of incoming e-mails cannot be guaranteed. All liability of
> Vontobel Holding Ltd. and any of its affiliates (hereinafter collectively
> referred to as "Vontobel Group") for any damages resulting from e-mail use
> is excluded. You are advised that urgent and time sensitive messages should
> not be sent by e-mail and if verification is required please request a
> printed version. Please note that all e-mail communications to and from the
> Vontobel Group are subject to electronic storage and review by Vontobel
> Group. Unless stated to the contrary and without prejudice to any
> contractual agreements between you and Vontobel Group which shall prevail
> in any case, e-mail-communication is for informational purposes only and is
> not intended as an offer or solicitation for the purchase or sale of any
> financial instrument or as an official confirmation of any transaction.
> The legal basis for the processing of your personal data is the legitimate
> interest to develop a commercial relationship with you, as well as your
> consent to forward you commercial communications. You can exercise, at any
> time and under the terms established under current regulation, your rights.
> If you prefer not to receive any further communications, please contact
> your client relationship manager if you are a client of Vontobel Group or
> notify the sender. Please note for an exact reference to the affected group
> entity the corporate e-mail signature. For further information about data
> privacy at Vontobel Group please consult www.vontobel.com.
>

--
http://www.freelists.org/webpage/oracle-l