Re: intermittent long "log file sync" waits

resending. (went to moderator b/c of message length)

On Tue, Jan 28, 2020 at 2:53 PM Chris Stephens <cstephens16_at_gmail.com> wrote:

> how about below?
>
> SQL> _at_ashtop event2 1=1 "TIMESTAMP'2020-01-28 12:46:25'"
> "TIMESTAMP'2020-01-28 12:48:45'"
> TOTALSECONDS AAS %This EVENT2
> FIRST_SEEN LAST_SEEN DIST_SQLEXEC_SEEN
> _______________ ______ __________ _______________________________
> ______________________ ______________________ ____________________
> 223 1.6 53% | Disk file operations I/O
> 2020-01-28 12:46:26 2020-01-28 12:48:44 1
> 115 0.8 27% | log file sync
> 2020-01-28 12:46:28 2020-01-28 12:48:44 1
> 34 0.2 8% | control file sequential read
> 2020-01-28 12:46:30 2020-01-28 12:48:40 1
> 31 0.2 7% | ON CPU
> 2020-01-28 12:46:27 2020-01-28 12:48:41 4
> 20 0.1 5% | RMAN backup & recovery I/O
> 2020-01-28 12:46:25 2020-01-28 12:48:21 1
> 1 0 0% | DFS lock handle
> 2020-01-28 12:47:40 2020-01-28 12:47:40 1
>
>
> 6 rows selected.
>
>
> SQL> _at_ashtop event2,program2 1=1 "TIMESTAMP'2020-01-28 12:46:25'"
> "TIMESTAMP'2020-01-28 12:48:45'"
> TOTALSECONDS AAS %This EVENT2
> PROGRAM2 FIRST_SEEN LAST_SEEN DIST_SQLEXEC_SEEN
> _______________ ______ __________ _______________________________
> _______________ ______________________ ______________________
> ____________________
> 223 1.6 53% | Disk file operations I/O (TNS
> Vn-Vn) 2020-01-28 12:46:26 2020-01-28 12:48:44
> 1
> 111 0.8 26% | log file sync (python)
> 2020-01-28 12:46:28 2020-01-28 12:48:44 1
> 34 0.2 8% | control file sequential read (TNS
> Vn-Vn) 2020-01-28 12:46:30 2020-01-28 12:48:40
> 1
> 20 0.1 5% | RMAN backup & recovery I/O (TNS
> Vn-Vn) 2020-01-28 12:46:25 2020-01-28 12:48:21
> 1
> 16 0.1 4% | ON CPU (TNS
> Vn-Vn) 2020-01-28 12:46:27 2020-01-28 12:48:40
> 1
> 5 0 1% | ON CPU (python)
> 2020-01-28 12:48:00 2020-01-28 12:48:41 4
> 4 0 1% | ON CPU (DIAn)
> 2020-01-28 12:46:41 2020-01-28 12:48:04 1
> 4 0 1% | log file sync
> (sqlplus) 2020-01-28 12:48:02 2020-01-28 12:48:05
> 1
> 3 0 1% | ON CPU (PSPn)
> 2020-01-28 12:47:43 2020-01-28 12:48:19 1
> 2 0 0% | ON CPU (LMON)
> 2020-01-28 12:46:36 2020-01-28 12:48:36 1
> 1 0 0% | DFS lock handle (SMON)
> 2020-01-28 12:47:40 2020-01-28 12:47:40 1
> 1 0 0% | ON CPU (IMRn)
> 2020-01-28 12:47:50 2020-01-28 12:47:50 1
>
>
> 12 rows selected.
>
>
> SQL> _at_ashtop event2,program2,p1,p2,p3 1=1 "TIMESTAMP'2020-01-28 12:46:25'"
> "TIMESTAMP'2020-01-28 12:48:45'"
> TOTALSECONDS AAS %This EVENT2
> PROGRAM2 P1 P2 P3 FIRST_SEEN
> LAST_SEEN DIST_SQLEXEC_SEEN
> _______________ ______ __________ _______________________________
> _______________ _____________ ____________ _____________
> ______________________ ______________________ ____________________
> 223 1.6 53% | Disk file operations I/O (TNS
> Vn-Vn) 2 0 4 2020-01-28 12:46:26
> 2020-01-28 12:48:44 1
> 16 0.1 4% | RMAN backup & recovery I/O (TNS
> Vn-Vn) 1 256 4294967295 2020-01-28 12:46:25
> 2020-01-28 12:48:05 1
> 5 0 1% | ON CPU (TNS
> Vn-Vn) 1413697536 1 0 2020-01-28 12:46:39
> 2020-01-28 12:48:15 1
> 5 0 1% | ON CPU (python)
> 1413697536 1 0 2020-01-28 12:48:00
> 2020-01-28 12:48:41 4
> 4 0 1% | control file sequential read (TNS
> Vn-Vn) 0 1 1 2020-01-28 12:47:19
> 2020-01-28 12:48:38 1
> 3 0 1% | ON CPU (PSPn)
> 100 0 0 2020-01-28 12:47:43
> 2020-01-28 12:48:19 1
> 3 0 1% | control file sequential read (TNS
> Vn-Vn) 0 1496 1 2020-01-28 12:46:30
> 2020-01-28 12:48:04 1
> 3 0 1% | control file sequential read (TNS
> Vn-Vn) 0 2217 1 2020-01-28 12:47:08
> 2020-01-28 12:47:54 1
> 3 0 1% | log file sync (python)
> 101758 971741255 0 2020-01-28 12:46:33
> 2020-01-28 12:46:35 1
> 3 0 1% | log file sync (python)
> 101832 971741286 0 2020-01-28 12:46:39
> 2020-01-28 12:46:41 1
> 3 0 1% | log file sync (python)
> 101877 971741304 0 2020-01-28 12:46:45
> 2020-01-28 12:46:47 1
> 3 0 1% | log file sync (python)
> 102096 971741450 0 2020-01-28 12:46:57
> 2020-01-28 12:46:59 1
> 3 0 1% | log file sync (python)
> 102169 971741479 0 2020-01-28 12:47:03
> 2020-01-28 12:47:05 1
> 3 0 1% | log file sync (python)
> 102197 971741493 0 2020-01-28 12:47:09
> 2020-01-28 12:47:11 1
> 3 0 1% | log file sync (python)
> 102226 971741510 0 2020-01-28 12:47:15
> 2020-01-28 12:47:17 1
>
>
> 15 rows selected.
>
>
> On Tue, Jan 28, 2020 at 2:45 PM Noveljic Nenad <
> nenad.noveljic_at_vontobel.com> wrote:
>
>>
>> This period wasn’t problematic, because max(log file sync wait time /
>> session )<= 1s which btw. also corresponds to the log file parallel write
>> wait time.
>>
>> We’d need to have the same report for a narrow time interval when the
>> long log file sync waits occurred.
>>
>>
>>

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