Re: intermittent long "log file sync" waits
Date: Tue, 28 Jan 2020 19:39:24 +0000
Message-ID: <LNXP265MB15629964FBB9B3A33ED5CC17A50A0_at_LNXP265MB1562.GBRP265.PROD.OUTLOOK.COM>
Basic premise - if "log file sync" timing isn't a reasonably close match for the "log file parallel write" timing then a prime suspect is CPU starvation. A secondary issue may be a large number of processes doing small amounts of work an committing, leading to a storm of processes restarting at the log writer clears them for action and is forced off the CPU as they all come on to the CPU (the failure to get PX processes on remote nodes to query gv$ views is an indicator that you're hitting your limit on processes which may be relevant to the log file sync problem).
Nenad's note on controlfile writes and log file switches is also relevant, of course - so checking log file sizing and completion time would be sensible, and cross-checking with v$sys_metric_history (if you get within the hour that it keeps) might give you some confirmation that the problem is highly localised in time.
Regards
Jonathan Lewis
From: oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> on behalf of Chris Stephens <cstephens16_at_gmail.com> Sent: 28 January 2020 18:59
To: Noveljic Nenad
Cc: oracle-l
Subject: 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<mailto: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<mailto:cstephens16_at_gmail.com>>
Datum Dienstag, 28. Jan. 2020, 5:43 PM
An: Noveljic Nenad <nenad.noveljic_at_vontobel.com<mailto:nenad.noveljic_at_vontobel.com>>
Cc: oracle-l <Oracle-L_at_freelists.org<mailto: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<mailto: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<mailto:oracle-l-bounce_at_freelists.org> <oracle-l-bounce_at_freelists.org<mailto: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<mailto: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<https://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<https://www.vontobel.com>.
-- http://www.freelists.org/webpage/oracle-lReceived on Tue Jan 28 2020 - 20:39:24 CET