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.