Re: intermittent long "log file sync" waits

  • From: Stefan Koehler <contact@xxxxxxxx>
  • To: cstephens16@xxxxxxxxx
  • Date: Wed, 29 Jan 2020 18:25:40 +0100 (CET)

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: @OracleSK

Chris Stephens <cstephens16@xxxxxxxxx> 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> @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@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@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@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@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@lsst-oradb05 (PSP0)                  2020-01-29 10:42:33    2020-01-29 
10:42:34                       1
              2      0    5% |    ON CPU                      
python@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@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@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@lsst-oradb04 (PPA7)                  2020-01-29 10:42:20    2020-01-29 
10:42:20                       1
              1      0    3% |    ON CPU                      
oracle@lsst-oradb05 (LMD1)                  2020-01-29 10:43:07    2020-01-29 
10:43:07                       1
              1      0    3% |    ON CPU                      
oracle@lsst-oradb05 (PPA7)                  2020-01-29 10:42:46    2020-01-29 
10:42:46                       1
              1      0    3% |    ON CPU                      
oracle@lsst-oradb06 (LCK1)                  2020-01-29 10:42:16    2020-01-29 
10:42:16                       1
              1      0    3% |    ON CPU                      
oracle@lsst-oradb06 (LMD0)                  2020-01-29 10:42:16    2020-01-29 
10:42:16                       1
              1      0    3% |    ON CPU                      
oracle@lsst-oradb06 (LMON)                  2020-01-29 10:42:31    2020-01-29 
10:42:31                       1
              1      0    3% |    ON CPU                      
oracle@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.
--
//www.freelists.org/webpage/oracle-l


Other related posts: