Re: intermittent long "log file sync" waits

  • From: Chris Stephens <cstephens16@xxxxxxxxx>
  • To: Noveljic Nenad <nenad.noveljic@xxxxxxxxxxxx>
  • Date: Tue, 28 Jan 2020 10:42:55 -0600

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

SQL> @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


8 rows selected.

SQL> @bg lgwr
   NAME    DESCRIPTION     SID    OPID     SPID               PADDR
      SADDR
_______ ______________ _______ _______ ________ ___________________
___________________
LGWR    Redo etc.         1710      34 26552    00000001E8718860
 00000001D8BFF4A0

On Tue, Jan 28, 2020 at 10:25 AM Noveljic Nenad <nenad.noveljic@xxxxxxxxxxxx>
wrote:

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@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> *On
Behalf Of *Chris Stephens
*Sent:* Dienstag, 28. Januar 2020 17:09
*To:* oracle-l <Oracle-L@xxxxxxxxxxxxx>
*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> @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.

Other related posts: