[20211229]再論19c latch free等待事件分析.txt
[20211229]再論19c latch free等待事件分析.txt
--//生產系統昨天例行檢查，發現19c再次出現latch free等待事件，再次分析看看。
--//以前的連結http://blog.itpub.net/267265/viewspace-2841664/ =>[20211111]19c latch free等待時間分析.txt
1.環境：
xxxx1> @pr
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 19.0.0.0.0
BANNER : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
BANNER_FULL : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.9.0.0.0
BANNER_LEGACY : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.檢查：
xxxx1> @ashtop event 1=1 &day
Total Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- --------
102094 1.2 80% | 2021-12-28 08:28:15 2021-12-29 08:28:14 62649 74687
14120 .2 11% | Failed Logon Delay 2021-12-28 08:28:16 2021-12-29 08:28:13 1 14087
3535 .0 3% | control file sequential read 2021-12-28 08:28:15 2021-12-29 08:27:36 89 3513
3232 .0 3% | latch free 2021-12-28 08:29:05 2021-12-29 08:27:56 50 2213
831 .0 1% | SQL*Net more data to client 2021-12-28 08:30:32 2021-12-29 08:26:48 45 826
628 .0 0% | log file parallel write 2021-12-28 08:28:50 2021-12-29 08:25:08 1 609
--//Failed Logon Delay 依舊沒有解決，無語。
--//我上次臨時關閉這個特性，估計伺服器資料庫發生了重啟，檢查。
SYS@XXXXX1/ORCLX> alter system set "_enable_spacebg"=false scope=memory;
System altered.
xxxx1> select INSTANCE_NUMBER,STARTUP_TIME,DATABASE_ROLE from DBA_HIST_DATABASE_INSTANCE where STARTUP_TIME>=sysdate-20;
INSTANCE_NUMBER STARTUP_TIME DATABASE_ROLE
--------------- ----------------------- ----------------
1 2021-12-12 16:45:14.000 PRIMARY
2 2021-12-12 16:47:47.000 PRIMARY
--//可以發現確實重啟過伺服器資料庫，難道這個問題是bug嗎？一天出現latch free 等待事件佔3232秒，平均到每小時並不多。
3.分析探究：
xxxx1> @ev_name "latch free"
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS DISPLAY_NAME CON_ID
------ ---------- ----------------------------- ---------- ---------- ---------- ------------- ----------- --------------- ----------------------------- ------
529 3474287957 latch free address number why 1893977003 0 Other latch free 0
531 2530878290 wait list latch free address number 1893977003 0 Other wait list latch free 0
646 3765978937 GL: cross instance latch free 1893977003 0 Other GL: cross instance latch free 0
--//P1對於地址。
xxxx1> @ashtop lower(module),sql_id,p1 "event='latch free'" &day
Total Distinct Distinct
Seconds AAS %This LOWER(MODULE) SQL_ID P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps
--------- ------- ------- ------------- ------------- ---------- ------------------- ------------------- ---------- --------
3091 .0 95% | ktsj 1611087616 2021-12-28 08:38:07 2021-12-29 08:36:27 1 2149
145 .0 4% | ktsj f3yfg50ga0r8n 1611087616 2021-12-28 08:44:26 2021-12-29 08:34:50 50 142
2 .0 0% | 1611000448 2021-12-28 23:57:01 2021-12-29 00:46:00 1 2
--//即使是sql語句，也是module=ktsj產生的。
xxxx1> @ wcy &5min "event='latch free'"
-- Display ASH Wait Chain Signatures script v0.6 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS #Blkrs WAIT_CHAIN FIRST_SEEN LAST_SEEN
------ ---------- ------- ------ ------------------------------------------------------------------------------------------------ ------------------- -------------------
20% 2 .0 1 -> 5741,15124,@1=>619,42003,@1=>latch free -> [idle blocker 1,5741,15124 (oracle@oda1 (SMCO))] 2021-12-29 08:34:15 2021-12-29 08:35:51
10% 1 .0 1 -> 5741,15124,@1=>1220,34429,@1=>latch free -> [idle blocker 1,5741,15124 (oracle@oda1 (SMCO))] 2021-12-29 08:38:15 2021-12-29 08:38:15
10% 1 .0 1 -> 5741,15124,@1=>617,46080,@1=>latch free -> [idle blocker 1,5741,15124 (oracle@oda1 (SMCO))] 2021-12-29 08:35:03 2021-12-29 08:35:03
10% 1 .0 1 -> 5741,50215,@2=>1215,13204,@2=>latch free -> [idle blocker 2,5741,50215 (oracle@oda2 (SMCO))] 2021-12-29 08:34:05 2021-12-29 08:34:05
10% 1 .0 1 -> 5741,50215,@2=>912,8474,@2=>latch free -> [idle blocker 2,5741,50215 (oracle@oda2 (SMCO))] 2021-12-29 08:34:50 2021-12-29 08:34:50
10% 1 .0 1 -> 5741,15124,@1=>909,65363,@1=>latch free -> [idle blocker 1,5741,15124 (oracle@oda1 (SMCO))] 2021-12-29 08:35:51 2021-12-29 08:35:51
10% 1 .0 1 -> 5741,15124,@1=>915,29003,@1=>latch free -> [idle blocker 1,5741,15124 (oracle@oda1 (SMCO))] 2021-12-29 08:38:15 2021-12-29 08:38:15
10% 1 .0 1 -> 5741,50215,@2=>909,22979,@2=>latch free -> [idle blocker 2,5741,50215 (oracle@oda2 (SMCO))] 2021-12-29 08:38:03 2021-12-29 08:38:03
10% 1 .0 1 -> 2122,26873,@2=>1215,13204,@2=>latch free -> [idle blocker 2,2122,26873 (oracle@oda2 (W005))] 2021-12-29 08:36:27 2021-12-29 08:36:27
9 rows selected.
xxxx1> @bgx w00
PROGRAM MODULE ACTION SID PID SPID
------------------ ------ ----------- ----- ------- ------
oracle@oda1 (W000) KTSJ KTSJ Slave 304 41 22889
oracle@oda1 (W001) KTSJ KTSJ Slave 909 43 22911
oracle@oda1 (W002) KTSJ KTSJ Slave 611 102 46259
oracle@oda1 (W003) KTSJ KTSJ Slave 2121 107 33388
oracle@oda1 (W004) KTSJ KTSJ Slave 2768 189 80228
oracle@oda1 (W005) KTSJ KTSJ Slave 617 222 83251
oracle@oda1 (W006) KTSJ KTSJ Slave 312 221 83363
oracle@oda1 (W007) KTSJ KTSJ Slave 915 223 83429
oracle@oda1 (W008) KTSJ KTSJ Slave 1220 224 83445
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
oracle@oda1 (W009) KTSJ KTSJ Slave 1518 225 83620
oracle@oda1 (W00A) KTSJ KTSJ Slave 1533 425 10988
oracle@oda1 (W00B) KTSJ KTSJ Slave 2127 347 90810
oracle@oda1 (W00C) KTSJ KTSJ Slave 5164 417 91732
oracle@oda1 (W00D) KTSJ KTSJ Slave 2728 229 83938
oracle@oda1 (W00E) KTSJ KTSJ Slave 3029 230 83974
oracle@oda1 (W00F) KTSJ KTSJ Slave 3332 231 97689
oracle@oda1 (W00G) KTSJ KTSJ Slave 3632 232 84006
oracle@oda1 (W00H) KTSJ KTSJ Slave 4236 234 84059
oracle@oda1 (W00I) KTSJ KTSJ Slave 4843 236 31224
oracle@oda1 (W00J) KTSJ KTSJ Slave 2782 429 20932
oracle@oda1 (W00K) KTSJ KTSJ Slave 5144 237 84249
oracle@oda1 (W00L) KTSJ KTSJ Slave 5446 238 84271
oracle@oda1 (W00M) KTSJ KTSJ Slave 10 240 84285
oracle@oda1 (W00N) KTSJ KTSJ Slave 47 360 58385
oracle@oda1 (W00O) KTSJ KTSJ Slave 619 242 84429
oracle@oda1 (W00P) KTSJ KTSJ Slave 917 243 84449
oracle@oda1 (W00Q) KTSJ KTSJ Slave 41 320 64141
oracle@oda1 (W00R) KTSJ KTSJ Slave 4235 194 84620
oracle@oda1 (W00S) KTSJ KTSJ Slave 3075 1090 48190
oracle@oda1 (W00T) KTSJ KTSJ Slave 1825 246 84802
oracle@oda1 (W00U) KTSJ KTSJ Slave 2128 247 84831
oracle@oda1 (W00V) KTSJ KTSJ Slave 3031 250 84867
oracle@oda1 (W00W) KTSJ KTSJ Slave 2730 249 84978
oracle@oda1 (W00X) KTSJ KTSJ Slave 3635 252 85147
oracle@oda1 (W00Y) KTSJ KTSJ Slave 3039 350 4827
oracle@oda1 (W00Z) KTSJ KTSJ Slave 5448 258 85211
36 rows selected.
--//我執行在例項1，仔細看sid=619,1220,617,909,915,都是這些W00X的後臺程式。我估計遇到了bug。
--//是否是應該這些後臺程式啟動太多了，我看了exadata 11g僅僅啟動1個。
exadate> @bgx w00
PROGRAM MODULE ACTION SID PID SPID
---------------------------------- ------------ ----------- ----- ------- ------
oracle@dm01dbadm01(W000) KTSJ KTSJ Slave 5505 343 23775
xxxx1> @pv 36
Show parameter which have value 36
no rows selected
--//依舊無法解決，先臨時關閉它：
xxxx1> alter system set "_enable_spacebg"=false scope=both;
System altered.
xxxx1> host sleep 60
xxxx1> @ wcy &1min "event='latch free'"
-- Display ASH Wait Chain Signatures script v0.6 BETA by Tanel Poder ( http://blog.tanelpoder.com )
no rows selected
xxxx1> @bgx w00
no rows selected
xxxx1> @bgx smco
no rows selected
4.附上wcy.sql,bgx.sql指令碼：
xxxx1> define 5min
DEFINE 5MIN = "sysdate-5/1440 sysdate" (CHAR)
$ cat wcy.sql
@ tpt/ash/ash_wait_chains BLOCKING_SESSION||','||BLOCKING_SESSION_SERIAL#||',@'||BLOCKING_INST_ID||'=>'||session_id||','||SESSION_SERIAL#||',@'||inst_id||'=>'||event "&&3" &&1 &&2
$ cat bgx.sql
select s.program, s.module, s.action, s.sid, p.pid, p.spid
from v$session s, v$process p
where s.paddr=p.addr and S.PROGRAM like upper('%&1%') and p.background=1
order by s.program;
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2849827/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20211111]19c latch free等待時間分析.txt
- Latch free等待事件(轉)事件
- Latch free等待事件四(轉)事件
- Latch free等待事件三(轉)事件
- Latch free等待事件二(轉)事件
- [異常等待事件latch undo global data]分析事件
- [20210418]CBC latch再討論3.txt
- [20210419]CBC latch再討論4.txt
- [20210413]CBC latch再討論2.txt
- latch等待事件彙總事件
- latch:library cache lock等待事件事件
- [20190423]簡單測試latch nowilling等待模式.txt模式
- [20191203]大量resmgrcpu quantum等待事件.txt事件
- [20191125]探究等待事件的本源.txt事件
- [20220518]enq FU - contention等待事件.txtENQ事件
- [20201117]解析cursor pin S等待事件.txt事件
- [20220531]inactive session等待事件2.txtSession事件
- [20220531]模擬inactive session等待事件.txtSession事件
- [重慶思莊每日技術分享]-free buffer waits 等待事件AI事件
- [20191126]探究等待事件的本源2.txt事件
- [20191127]探究等待事件的本源4.txt事件
- read by other session 等待事件分析Session事件
- [20240827]分析為什麼出現library cache lock等待事件2.txt事件
- [20240828]分析為什麼出現library cache lock等待事件5.txt事件
- Oracle 19c中的等待事件分類 Event WaitsOracle事件AI
- [20201204]關於等待事件Log File Sync.txt事件
- DB BUFFER LRU 列表的latch等待
- 碰到一個latch free相關的BUG
- [20180918]等待事件SQL/Net more data from client.txt事件SQLclient
- [20180925]等待事件SQLNet more data from client 6.txt事件SQLclient
- [20180922]等待事件SQLNet more data from client 4.txt事件SQLclient
- [20180920]等待事件SQLNet more data from client 3.txt事件SQLclient
- [20180926]等待事件SQLNet more data from client 7.txt事件SQLclient
- [20211031]18c row cache mutext等待事件探究.txtMutex事件
- [20210315]理解db file parallel read等待事件3.txtParallel事件
- [20210315]理解db file parallel read等待事件4.txtParallel事件
- [20210207]使用gdb檢視等待事件11g.txt事件
- enq: TX - allocate ITL entry等待事件分析ENQ事件