Re: intermittent long "log file sync" waits

Hello Chris,
are you sure that the python program was suffered by high "log file sync" latency in this snippet?

Of course this is an ASH time frame of 1 minute but the data can also mean that you almost spent no end user response time on it as these are just 1 second samples and you may snapped a few low latency ones here. If you wanna be sure about latency you also need some other data from this time frame as well (e.g. you can use Luca Canali's scripts for that - https://db-blog.web.cern.ch/blog/luca-canali/2015-06-event-histogram-metric-and-oracle-12c )

P.S.: I usually don't like to do some shameless ad but if this issue drives you really crazy you might wanna consider a few hours of my consulting services. I also bill in USD ;-)

Best Regards
Stefan Koehler

Independent Oracle performance consultant and researcher Website: http://www.soocs.de
Twitter: _at_OracleSK

> Chris Stephens <cstephens16_at_gmail.com> hat am 29. Januar 2020 um 17:51 geschrieben:
>
>
> Here is some correlated ASH output showing log file sync w/ psnapper on lgwr at same time:
>  
> SQL> _at_ashtop event2,program 1=1 sysdate-1/60/24 sysdate
>    TOTALSECONDS    AAS      %This                      EVENT2                                     PROGRAM             FIRST_SEEN              LAST_SEEN    DIST_SQLEXEC_SEEN
> _______________ ______ __________ ___________________________ ___________________________________________ ______________________ ______________________ ____________________
>              10    0.2   26% |    ON CPU                      sqlplus_at_lsst-oradb05 (TNS V1-V3)            2020-01-29 10:42:19    2020-01-29 10:43:09                       5
>               4    0.1   11% |    ON CPU                      sqlplus_at_lsst-verify-worker28 (TNS V1-V3)    2020-01-29 10:43:04    2020-01-29 10:43:07                       3
>               4    0.1   11% |    log file sync               python_at_lsst-verify-worker28 (TNS V1-V3)     2020-01-29 10:42:10    2020-01-29 10:42:13                       1
>               3    0.1    8% |    ON CPU                      sqlplus_at_lsst-verify-worker45 (TNS V1-V3)    2020-01-29 10:42:15    2020-01-29 10:42:20                       2
>               2      0    5% |    ON CPU                      oracle_at_lsst-oradb05 (PSP0)                  2020-01-29 10:42:33    2020-01-29 10:42:34                       1
>               2      0    5% |    ON CPU                      python_at_lsst-verify-worker28 (TNS V1-V3)     2020-01-29 10:42:32    2020-01-29 10:43:09                       2
>               2      0    5% |    ON CPU                      python_at_lsst-verify-worker45 (TNS V1-V3)     2020-01-29 10:42:22    2020-01-29 10:42:23                       2
>               2      0    5% |    row cache lock              sqlplus_at_lsst-verify-worker45 (TNS V1-V3)    2020-01-29 10:42:16    2020-01-29 10:42:18                       2
>               1      0    3% |    IPC send completion sync    oracle_at_lsst-oradb04 (PPA7)                  2020-01-29 10:42:20    2020-01-29 10:42:20                       1
>               1      0    3% |    ON CPU                      oracle_at_lsst-oradb05 (LMD1)                  2020-01-29 10:43:07    2020-01-29 10:43:07                       1
>               1      0    3% |    ON CPU                      oracle_at_lsst-oradb05 (PPA7)                  2020-01-29 10:42:46    2020-01-29 10:42:46                       1
>               1      0    3% |    ON CPU                      oracle_at_lsst-oradb06 (LCK1)                  2020-01-29 10:42:16    2020-01-29 10:42:16                       1
>               1      0    3% |    ON CPU                      oracle_at_lsst-oradb06 (LMD0)                  2020-01-29 10:42:16    2020-01-29 10:42:16                       1
>               1      0    3% |    ON CPU                      oracle_at_lsst-oradb06 (LMON)                  2020-01-29 10:42:31    2020-01-29 10:42:31                       1
>               1      0    3% |    ON CPU                      oracle_at_lsst-oradb06 (M001)                  2020-01-29 10:43:06    2020-01-29 10:43:06                       1
>
>
> 15 rows selected.
>
>
> Wed Jan 29 10:42:12 CST 2020
>
> Linux Process Snapper v0.14 by Tanel Poder [https://tp.dev/psnapper]
> Sampling /proc/syscall, wchan, cmdline, stat for 5 seconds... finished.
>
>
> === Active Threads ==========================================================================
>
>  samples | avg_threads | cmdline           | state            | syscall    | wchan
> ---------------------------------------------------------------------------------------------
>        4 |        0.04 | ora_lgwr_lsst2db2 | Running (ON CPU) | semtimedop | SYSC_semtimedop
>
>
> samples: 100 (expected: 100)
> total processes: 1, threads: 1
> runtime: 5.00, measure time: 0.50
>
> Wed Jan 29 10:42:17 CST 2020
>
> Linux Process Snapper v0.14 by Tanel Poder [https://tp.dev/psnapper]
> Sampling /proc/syscall, wchan, cmdline, stat for 5 seconds... finished.
>
>
> === Active Threads ==========================================================================
>
>  samples | avg_threads | cmdline           | state            | syscall    | wchan
> ---------------------------------------------------------------------------------------------
>        1 |        0.01 | ora_lgwr_lsst2db2 | Running (ON CPU) | semtimedop | SYSC_semtimedop
>        1 |        0.01 | ora_lgwr_lsst2db2 | Running (ON CPU) | semtimedop | read_events
>
>  
> neither of the Log Writer Slave processes showed any activity via psnapper.

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