Re: intermittent long "log file sync" waits

From: Chris Stephens <cstephens16_at_gmail.com>
Date: Tue, 28 Jan 2020 13:44:06 -0600
Message-ID: <CAEFL0sxAZAK3Ju9Rqv6bAGcyPwHxxFTwaxgsHtUV0BuFZJyUhg_at_mail.gmail.com>



i don't have a way to reproduce on demand. is the best way to just write a loop hoping to catch a good/bad stack that coincides w/ log file sync? if so, what command to stick in loop?

On Tue, Jan 28, 2020 at 1:35 PM Noveljic Nenad <nenad.noveljic_at_vontobel.com> wrote:

> Also for any other bg processes - that’s unusual.
>
> Any possibility to capture pstack on lg* processes when this happens?
>
>
>
>
> *Von: *Chris Stephens <cstephens16_at_gmail.com>
> *Datum *Dienstag, 28. Jan. 2020, 8:20 PM
> *An: *Noveljic Nenad <nenad.noveljic_at_vontobel.com>
> *Cc: *oracle-l <Oracle-L_at_freelists.org>
> *Betreff: *Re: intermittent long "log file sync" waits
>
> doesn't look like any ash data for lgwr:
>
> SQL> _at_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> _at_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_at_vontobel.com> 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.
>>
>>
>>
>>
>> *Von: *Chris Stephens <cstephens16_at_gmail.com>
>> *Datum *Dienstag, 28. Jan. 2020, 7:59 PM
>> *An: *Noveljic Nenad <nenad.noveljic_at_vontobel.com>
>> *Cc: *oracle-l <Oracle-L_at_freelists.org>
>> *Betreff: *Re: intermittent long "log file sync" waits
>>
>> probably just 19c RAC
>>
>> SQL> _at_ash_wait_chains event2 session_id=1713 "TIMESTAMP'2020-01-27
>> 15:50:48'" "TIMESTAMP'2020-01-27 15:52:40'"
>>
>> -- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder (
>> http://blog.tanelpoder.com )
>>
>> , TO_CHAR(CASE WHEN session_state = 'WAITING' THEN p1 ELSE null
>> END, '0XXXXXXXXXXXXXXX') p1hex
>> *
>> ERROR at line 14:
>> ORA-12850: Could not allocate slaves on all specified instances: 3
>> needed, 1 allocated
>>
>> SQL>
>> Session: c2
>>
>> On Tue, Jan 28, 2020 at 11:30 AM Noveljic Nenad <
>> nenad.noveljic_at_vontobel.com> wrote:
>>
>>> The script should work with 19. It must be something else. Could you try
>>> with ash_wait_chains2 - 2 is the rac version? For start, I would group only
>>> on event2 (the first parameter).
>>>
>>> If it doesn’t work, please post the error message.
>>>
>>>
>>>
>>> *Von: *Chris Stephens <cstephens16_at_gmail.com>
>>> *Datum *Dienstag, 28. Jan. 2020, 5:43 PM
>>> *An: *Noveljic Nenad <nenad.noveljic_at_vontobel.com>
>>> *Cc: *oracle-l <Oracle-L_at_freelists.org>
>>> *Betreff: *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
>>>
>>>
>>> 8 rows selected.
>>>
>>> SQL> _at_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_at_vontobel.com> 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_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.
>>>>
>>>
>>> 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.
>>>
>>
>> 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.
>>
>
> 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
Received on Tue Jan 28 2020 - 20:44:06 CET

Original text of this message