Re: intermittent long "log file sync" waits
Date: Wed, 29 Jan 2020 08:58:10 -0600
Message-ID: <CAEFL0sxzLFSFC65wxQiiJAm7EV75Zk10L+CDtW87FW5PReLjDg_at_mail.gmail.com>
yep. when i got in this morning, rman processes were still stuck.
here is output from problem time yesterday as best i can estimate it:
SQL> _at_ashtop event2 1=1 "TIMESTAMP'2020-01-28 16:35:00'" "TIMESTAMP'2020-01-28 16:45:00'"
TOTALSECONDS AAS %This
EVENT2 FIRST_SEEN LAST_SEEN DIST_SQLEXEC_SEEN
_______________ ______ __________
____________________________________________ ______________________
______________________ ____________________
246 0.4 85% | ON CPU
2020-01-28 16:35:01 2020-01-28 16:44:55 96
10 0 3% | log file sync
2020-01-28 16:36:16 2020-01-28 16:40:46 1
7 0 2% | DLM cross inst call completion
2020-01-28 16:36:02 2020-01-28 16:44:14 7
4 0 1% | library cache lock
2020-01-28 16:35:00 2020-01-28 16:44:16 4
4 0 1% | library cache pin
2020-01-28 16:38:31 2020-01-28 16:43:05 4
3 0 1% | PX Deq: Slave Session Stats
2020-01-28 16:39:28 2020-01-28 16:43:28 2
3 0 1% | enq: PS - contention [mode=6]
2020-01-28 16:38:00 2020-01-28 16:43:28 3
2 0 1% | PX Deq: Join ACK
2020-01-28 16:41:10 2020-01-28 16:42:38 2
2 0 1% | log file parallel write
2020-01-28 16:36:08 2020-01-28 16:40:52 1
1 0 0% | ASM file metadata operation
2020-01-28 16:39:24 2020-01-28 16:39:24 1
1 0 0% | IPC send completion sync
2020-01-28 16:40:07 2020-01-28 16:40:07 1
1 0 0% | KJC: Wait for msg sends to complete
2020-01-28 16:42:00 2020-01-28 16:42:00 1
1 0 0% | control file sequential read
2020-01-28 16:41:55 2020-01-28 16:41:55 1
1 0 0% | enq: CR - block range reuse ckpt [mode=6]
2020-01-28 16:43:06 2020-01-28 16:43:06 1
1 0 0% | enq: ZH - compression analysis [mode=6]
2020-01-28 16:41:54 2020-01-28 16:41:54 1
15 rows selected.
SQL> _at_ashtop event2,program 1=1 "TIMESTAMP'2020-01-28 16:35:00'" "TIMESTAMP'2020-01-28 16:45:00'"
TOTALSECONDS AAS %This EVENT2
PROGRAM FIRST_SEEN
LAST_SEEN DIST_SQLEXEC_SEEN
_______________ ______ __________ _________________________________
___________________________________________ ______________________
______________________ ____________________
114 0.2 39% | ON CPU
sqlplus_at_lsst-oradb05 (TNS V1-V3) 2020-01-28 16:35:02
2020-01-28 16:44:55 49
48 0.1 16% | ON CPU
python_at_lsst-verify-worker28 (TNS V1-V3) 2020-01-28 16:35:01
2020-01-28 16:44:44 25
27 0 9% | ON CPU
sqlplus_at_lsst-verify-worker28 (TNS V1-V3) 2020-01-28 16:36:03
2020-01-28 16:44:15 19
9 0 3% | log file sync
sqlplus_at_lsst-verify-worker28 (TNS V1-V3) 2020-01-28 16:37:12
2020-01-28 16:40:46 1
6 0 2% | ON CPU
oracle_at_lsst-oradb04 (LMON) 2020-01-28 16:35:04
2020-01-28 16:44:05 1
6 0 2% | ON CPU
oracle_at_lsst-oradb05 (LMD1) 2020-01-28 16:37:23
2020-01-28 16:44:16 1
5 0 2% | ON CPU
oracle_at_lsst-oradb05 (LMON) 2020-01-28 16:35:49
2020-01-28 16:39:50 1
4 0 1% | DLM cross inst call completion
sqlplus_at_lsst-verify-worker28 (TNS V1-V3) 2020-01-28 16:36:02
2020-01-28 16:44:14 4
4 0 1% | ON CPU
oracle_at_lsst-oradb04 (DIA0) 2020-01-28 16:35:01
2020-01-28 16:42:44 1
3 0 1% | DLM cross inst call completion
python_at_lsst-verify-worker28 (TNS V1-V3) 2020-01-28 16:38:27
2020-01-28 16:43:15 3
3 0 1% | ON CPU
oracle_at_lsst-oradb04 (GEN1) 2020-01-28 16:42:44
2020-01-28 16:42:59 1
3 0 1% | ON CPU
oracle_at_lsst-oradb04 (LMD0) 2020-01-28 16:37:18
2020-01-28 16:40:40 1
3 0 1% | ON CPU
oracle_at_lsst-oradb05 (DBRM) 2020-01-28 16:38:40
2020-01-28 16:38:46 1
3 0 1% | ON CPU
oracle_at_lsst-oradb05 (DIA0) 2020-01-28 16:36:39
2020-01-28 16:38:30 1
3 0 1% | ON CPU
oracle_at_lsst-oradb05 (LMD0) 2020-01-28 16:36:06
2020-01-28 16:43:15 1
15 rows selected.
On Wed, Jan 29, 2020 at 8:45 AM Noveljic Nenad <nenad.noveljic_at_vontobel.com> wrote:
> The total log file sync time wait time was <= 5s in 5.5 minutes, so this
> doesn’t seem to be a problem within the observed time period.
>
>
>
> To speed-up the backups you’d need to analyze the I/O performance on the
> backup and control file devices. This might or might not correlate with the
> log file sync problem.
>
>
>
> Note that you specified sysdate-10/60/24 and sysdate for begin and end
> time, respectively, which will show you the report for the last 10
> minutes, and not for the yesterday’s time interval when you reported the
> backup issue : “noticed the archivelog backup scheduled to run every hour
> seems to be stuck and has been for at least 10 mins:“
>
>
>
>
>
> *From:* Chris Stephens <cstephens16_at_gmail.com>
> *Sent:* Mittwoch, 29. Januar 2020 14:50
> *To:* Noveljic Nenad <nenad.noveljic_at_vontobel.com>
> *Cc:* cary.millsap_at_method-r.com; Stefan Koehler <contact_at_soocs.de>;
> oracle-l <Oracle-L_at_freelists.org>
> *Subject:* Re: intermittent long "log file sync" waits
>
>
>
> SQL> _at_ashtop event2 1=1 sysdate-10/60/24 sysdate
> TOTALSECONDS AAS %This
> EVENT2 FIRST_SEEN LAST_SEEN DIST_SQLEXEC_SEEN
> _______________ ______ __________
> _________________________________________ ______________________
> ______________________ ____________________
> 1864 3.1 67% | Disk file operations I/O
> 2020-01-29 07:38:53 2020-01-29 07:48:52 925
> 469 0.8 17% | ON CPU
> 2020-01-29 07:38:53 2020-01-29 07:48:45 112
> 299 0.5 11% | control file sequential read
> 2020-01-29 07:38:53 2020-01-29 07:48:49 112
> 61 0.1 2% | ASM file metadata operation
> 2020-01-29 07:39:22 2020-01-29 07:43:02 12
> 13 0 0% | enq: RS - prevent file delete [mode=2]
> 2020-01-29 07:39:07 2020-01-29 07:47:09 8
> 9 0 0% | RMAN backup & recovery I/O
> 2020-01-29 07:40:06 2020-01-29 07:48:44 8
> 7 0 0% | ADR block file write
> 2020-01-29 07:39:17 2020-01-29 07:46:46 1
> 7 0 0% | ADR file lock
> 2020-01-29 07:39:17 2020-01-29 07:46:46 1
> 7 0 0% | row cache lock
> 2020-01-29 07:41:22 2020-01-29 07:45:46 7
> 5 0 0% | DLM cross inst call completion
> 2020-01-29 07:41:15 2020-01-29 07:46:57 5
> 5 0 0% | log file sync
> 2020-01-29 07:42:31 2020-01-29 07:48:03 1
> 4 0 0% | KSV master wait
> 2020-01-29 07:39:22 2020-01-29 07:42:42 3
> 3 0 0% | reliable message
> 2020-01-29 07:47:00 2020-01-29 07:48:07 3
> 2 0 0% | library cache lock
> 2020-01-29 07:42:21 2020-01-29 07:44:42 2
> 1 0 0% | IMR slave acknowledgement msg
> 2020-01-29 07:41:04 2020-01-29 07:41:04 1
>
>
> 15 rows selected.
>
>
> SQL> _at_ashtop module,event2 1=1 sysdate-10/60/24 sysdate
> TOTALSECONDS AAS %This
> MODULE EVENT2 FIRST_SEEN
> LAST_SEEN DIST_SQLEXEC_SEEN
> _______________ ______ __________
> __________________________________________ _______________________________
> ______________________ ______________________ ____________________
> 934 1.6 34% | backup archivelog
> Disk file operations I/O 2020-01-29 07:39:07 2020-01-29
> 07:49:06 1
> 465 0.8 17% | rman_at_lsst-oradb04 (TNS V1-V3)
> Disk file operations I/O 2020-01-29 07:39:08 2020-01-29
> 07:49:06 465
> 460 0.8 17% | rman_at_lsst-oradb01 (TNS V1-V3)
> Disk file operations I/O 2020-01-29 07:39:08 2020-01-29
> 07:49:06 460
> 191 0.3 7% | backup archivelog
> control file sequential read 2020-01-29 07:39:17 2020-01-29
> 07:49:00 1
> 135 0.2 5% | SQL*Plus
> ON CPU 2020-01-29 07:39:07 2020-01-29
> 07:48:06 18
> 130 0.2 5% | sqlplus_at_lsst-oradb05 (TNS V1-V3)
> ON CPU 2020-01-29 07:39:16 2020-01-29
> 07:48:57 50
> 80 0.1 3% |
> ON CPU 2020-01-29 07:39:23 2020-01-29
> 07:48:34 2
> 60 0.1 2% | rman_at_lsst-oradb01 (TNS V1-V3)
> control file sequential read 2020-01-29 07:39:19 2020-01-29
> 07:48:57 60
> 57 0.1 2% | MMON_SLAVE
> ASM file metadata operation 2020-01-29 07:40:10 2020-01-29
> 07:43:02 11
> 52 0.1 2% | rman_at_lsst-oradb04 (TNS V1-V3)
> control file sequential read 2020-01-29 07:39:19 2020-01-29
> 07:48:57 52
> 41 0.1 1% | backup archivelog
> ON CPU 2020-01-29 07:39:17 2020-01-29
> 07:48:41 1
> 30 0.1 1% | python_at_lsst-verify-worker28 (TNS V1-V3)
> ON CPU 2020-01-29 07:41:18 2020-01-29
> 07:48:33 19
> 13 0 0% | rman_at_lsst-oradb01 (TNS V1-V3)
> ON CPU 2020-01-29 07:39:07 2020-01-29
> 07:48:54 12
> 13 0 0% | rman_at_lsst-oradb04 (TNS V1-V3)
> ON CPU 2020-01-29 07:39:15 2020-01-29
> 07:48:22 13
> 8 0 0% | backup archivelog
> ADR file lock 2020-01-29 07:39:17 2020-01-29
> 07:49:00 1
>
>
>
> On Wed, Jan 29, 2020 at 1:14 AM Noveljic Nenad <
> nenad.noveljic_at_vontobel.com> wrote:
>
> Hi Chris,
>
>
>
> Could you send the ashtop event2 1=1 _*from*_ _*to*_ output for the 10
> minutes interval while the backup was hanging?
>
>
>
> Let’s see if there was a log file sync problem at the same time.
>
>
>
> Best regards,
>
>
>
> Nenad
>
>
>
> https://nenadnoveljic.com/blog/
>
>
>
>
>
> *From:* Chris Stephens <cstephens16_at_gmail.com>
> *Sent:* Dienstag, 28. Januar 2020 23:49
> *To:* Noveljic Nenad <nenad.noveljic_at_vontobel.com>
> *Cc:* cary.millsap_at_method-r.com; Stefan Koehler <contact_at_soocs.de>;
> oracle-l <Oracle-L_at_freelists.org>
> *Subject:* Re: intermittent long "log file sync" waits
>
>
>
> was just getting ready to sign off and noticed the archivelog backup
> scheduled to run every hour seems to be stuck and has been for at least 10
> mins:
>
>
>
> [oracle_at_lsst-oradb04 ~]$ ps -ef | grep oracle_backup.sh
> oracle 13369 31167 0 16:43 pts/0 00:00:00 grep --color=auto
> oracle_backup.sh
> oracle 14649 14645 0 16:00 ? 00:00:00 /bin/bash
> /home/oracle/scripts/rman/oracle_backup.sh -d lsst2db -s archivelog.rman -c
> lsst2db_rman -e cs2018_at_ncsa.illinois.edu -r iddsdba_rman
> [oracle_at_lsst-oradb04 ~]$ pstack 15649
> Process 15649 not found.
> [oracle_at_lsst-oradb04 ~]$ pstack 14649
> #0 0x00007f9a6537e41c in waitpid () from /lib64/libc.so.6
> #1 0x0000000000440b84 in waitchld.isra.10 ()
> #2 0x0000000000441e3c in wait_for ()
> #3 0x0000000000433b0e in execute_command_internal ()
> #4 0x0000000000433d2e in execute_command ()
> #5 0x000000000041e365 in reader_loop ()
> #6 0x000000000041c9ce in main ()
> [oracle_at_lsst-oradb04 ~]$ pstack 14649
> #0 0x00007f9a6537e41c in waitpid () from /lib64/libc.so.6
> #1 0x0000000000440b84 in waitchld.isra.10 ()
> #2 0x0000000000441e3c in wait_for ()
> #3 0x0000000000433b0e in execute_command_internal ()
> #4 0x0000000000433d2e in execute_command ()
> #5 0x000000000041e365 in reader_loop ()
> #6 0x000000000041c9ce in main ()
> [oracle_at_lsst-oradb04 ~]$ pstack 14649
> #0 0x00007f9a6537e41c in waitpid () from /lib64/libc.so.6
> #1 0x0000000000440b84 in waitchld.isra.10 ()
> #2 0x0000000000441e3c in wait_for ()
> #3 0x0000000000433b0e in execute_command_internal ()
> #4 0x0000000000433d2e in execute_command ()
> #5 0x000000000041e365 in reader_loop ()
> #6 0x000000000041c9ce in main ()
> [oracle_at_lsst-oradb04 ~]$ pstack 14649
> #0 0x00007f9a6537e41c in waitpid () from /lib64/libc.so.6
> #1 0x0000000000440b84 in waitchld.isra.10 ()
> #2 0x0000000000441e3c in wait_for ()
> #3 0x0000000000433b0e in execute_command_internal ()
> #4 0x0000000000433d2e in execute_command ()
> #5 0x000000000041e365 in reader_loop ()
> #6 0x000000000041c9ce in main ()
> [oracle_at_lsst-oradb04 ~]$
>
>
>
> ____________________________________________________
>
> 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.
>
-- http://www.freelists.org/webpage/oracle-lReceived on Wed Jan 29 2020 - 15:58:10 CET