[20211229]再論19c latch free等待事件分析.txt

lfree發表於2021-12-29

[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/,如需轉載,請註明出處,否則將追究法律責任。

相關文章