[20211111]19c latch free等待时间分析.txt
--//前天遇到的问题,当时的分析有点乱,遇到一些奇怪的问题，自己今天做一些整理.
--//检查生产系统，出现latch free等待事件有一些靠前，分析看看。
1.环境：
SYS@XXXXX1/ORCLX> @ prxx
==============================
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.分析:
SYS@XXXXX1/ORCLX> @ ashtop event 1=1 trunc(sysdate) sysdate
Total
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN
--------- ------- ------- ---------------------------------------- ------------------- -------------------
52745 .9 75% | 2021-11-09 00:00:02 2021-11-09 16:56:57
10042 .2 14% | Failed Logon Delay 2021-11-09 00:00:04 2021-11-09 16:56:59
2368 .0 3% | control file sequential read 2021-11-09 00:00:42 2021-11-09 16:56:59
1445 .0 2% | latch free 2021-11-09 00:01:07 2021-11-09 16:56:50
724 .0 1% | SQL*Net more data to client 2021-11-09 03:11:22 2021-11-09 16:48:59
441 .0 1% | enq: SQ - contention 2021-11-09 15:53:56 2021-11-09 16:07:01
..
--//其它问题先不管,先前提交的问题都没有解决，无语。主要集中在等待事件latch free上.
SYS@XXXXX1/ORCLX> @ 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
--//latch free 第一个参数p1是latch address。
--//我发现集中在p1=1611087616.
SYS@XXXXX1/ORCLX> @ ashtop sql_id,event,p1 p1=1611087616 trunc(sysdate)-1 trunc(sysdate)
Total
Seconds AAS %This SQL_ID EVENT P1 FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------- ---------------------------------------- ---------- ------------------- -------------------
2127 .0 92% | latch free 1611087616 2021-11-09 00:01:07 2021-11-09 23:59:46
113 .0 5% | 1611087616 2021-11-09 00:07:26 2021-11-09 23:58:58
61 .0 3% | f3yfg50ga0r8n latch free 1611087616 2021-11-09 00:23:12 2021-11-09 23:55:51
2 .0 0% | 9x2prazfz86dz 1611087616 2021-11-09 15:02:30 2021-11-09 19:12:36
2 .0 0% | f3yfg50ga0r8n 1611087616 2021-11-09 00:47:18 2021-11-09 18:24:55
--//1611087616 = 0x60073f00
SYS@XXXXX1/ORCLX> select * from v$latch_children where addr=hextoraw('0000000060073f00');
no rows selected
SYS@XXXXX1/ORCLX> select * from v$latch_parent where addr=hextoraw('0000000060073f00')
2 @ prxx
==============================
ADDR : 0000000060073F00
LATCH# : 517
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~=> P2=517 ,对应LATCH#。
LEVEL# : 0
NAME : space background task latch
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HASH : 1314311971
GETS : 1444462
MISSES : 798314
SLEEPS : 700416
IMMEDIATE_GETS : 487163
IMMEDIATE_MISSES : 1603
WAITERS_WOKEN : 0
WAITS_HOLDING_LATCH : 0
SPIN_GETS : 98145
SLEEP1 : 0
SLEEP2 : 0
SLEEP3 : 0
SLEEP4 : 0
SLEEP5 : 0
SLEEP6 : 0
SLEEP7 : 0
SLEEP8 : 0
SLEEP9 : 0
SLEEP10 : 0
SLEEP11 : 0
WAIT_TIME : 199041612
CON_ID : 0
PL/SQL procedure successfully completed.
SYS@XXXXX1/ORCLX> select * from v$latch where addr=hextoraw('0000000060073f00')
2 @ prxx
==============================
ADDR : 0000000060073F00
LATCH# : 517
LEVEL# : 0
NAME : space background task latch
HASH : 1314311971
GETS : 1608487
MISSES : 888515
SLEEPS : 780457
IMMEDIATE_GETS : 542974
IMMEDIATE_MISSES : 1860
WAITERS_WOKEN : 0
WAITS_HOLDING_LATCH : 0
SPIN_GETS : 108330
SLEEP1 : 0
SLEEP2 : 0
SLEEP3 : 0
SLEEP4 : 0
SLEEP5 : 0
SLEEP6 : 0
SLEEP7 : 0
SLEEP8 : 0
SLEEP9 : 0
SLEEP10 : 0
SLEEP11 : 0
WAIT_TIME : 218601878
CON_ID : 0
PL/SQL procedure successfully completed.
--//也就是出现数据文件空间增加的情况。
SYS@XXXXX1/ORCLX> @ tpt/ash/ash_wait_chains BLOCKING_SESSION||','||BLOCKING_SESSION_SERIAL#||',@'||BLOCKING_INST_ID||'=>'||session_id||','||SESSION_SERIAL#||',@'||inst_id||'=>'||event "event='latch free'" sysdate-100 sysdate
-- 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
------ ---------- ------- ------ -------------------------------------------------------------------------- ------------------- -------------------
9% 414 .0 1 -> 5741,22079,@2=>623,49489,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:02:17 2021-11-10 09:48:38
8% 404 .0 1 -> 5741,22079,@2=>620,50618,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:03:53 2021-11-10 09:51:02
8% 384 .0 1 -> 5741,22079,@2=>319,21988,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:03:05 2021-11-10 09:35:09
7% 352 .0 1 -> 5741,22079,@2=>304,39734,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:07:02 2021-11-10 09:35:09
7% 333 .0 1 -> 5741,14347,@1=>617,1119,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:43:55 2021-11-10 09:46:59
7% 332 .0 1 -> 5741,14347,@1=>304,33924,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:20:52 2021-11-10 09:42:19
6% 296 .0 1 -> 5741,14347,@1=>313,35032,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:24:49 2021-11-10 09:35:09
5% 259 .0 1 -> 5741,22079,@2=>922,65278,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:04:41 2021-11-10 09:30:23
5% 259 .0 1 -> 5741,22079,@2=>909,59733,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:22:08 2021-11-10 09:37:30
5% 238 .0 1 -> 5741,22079,@2=>924,63040,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:05:29 2021-11-10 09:47:50
4% 172 .0 1 -> 5741,14347,@1=>920,33701,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:19:19 2021-11-10 09:43:56
4% 172 .0 1 -> 5741,14347,@1=>912,57351,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:19:19 2021-11-10 09:42:19
3% 166 .0 1 -> 5741,14347,@1=>909,2656,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:19:19 2021-11-10 09:41:31
3% 150 .0 1 -> 5741,22079,@2=>1218,46170,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:26:54 2021-11-10 09:43:52
1% 72 .0 1 -> 5741,14347,@1=>1220,2757,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:33:36 2021-11-10 08:55:27
1% 63 .0 1 -> 5741,14347,@1=>1222,27776,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:33:36 2021-11-10 08:18:18
1% 53 .0 1 -> 5741,22079,@2=>1522,52927,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 00:01:32 2021-11-10 09:49:26
1% 51 .0 1 -> 5741,22079,@2=>1517,50587,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 13:04:58 2021-11-10 09:51:02
1% 41 .0 1 -> 5741,22079,@2=>1528,19663,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-09 13:51:48 2021-11-10 09:04:10
1% 37 .0 1 -> ,,@=>922,65278,@2=>latch free 2021-11-08 01:29:40 2021-11-09 12:34:47
1% 34 .0 1 -> ,,@=>924,63040,@2=>latch free 2021-11-08 00:50:45 2021-11-09 10:38:05
1% 30 .0 1 -> 5741,14347,@1=>10,58694,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 11:18:04 2021-11-10 09:17:42
1% 30 .0 1 -> 5741,14347,@1=>1522,52719,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 10:24:04 2021-11-10 08:10:20
1% 28 .0 1 -> 5741,14347,@1=>12,25446,@1=>latch free -> [idle blocker 1,5741,14347] 2021-11-08 11:13:18 2021-11-10 08:15:05
0% 22 .0 1 -> 5741,22079,@2=>18,16175,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 05:55:34 2021-11-10 09:50:14
0% 21 .0 1 -> 5741,22079,@2=>16,50299,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 02:30:37 2021-11-10 08:00:41
0% 20 .0 1 -> ,,@=>909,59733,@2=>latch free 2021-11-08 00:12:36 2021-11-09 10:42:50
0% 20 .0 1 -> 5741,22079,@2=>1827,39734,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-09 03:55:36 2021-11-10 09:43:04
0% 17 .0 1 -> 5741,22079,@2=>3638,62933,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-08 04:01:13 2021-11-10 08:52:14
0% 17 .0 1 -> 5741,22079,@2=>1830,46599,@2=>latch free -> [idle blocker 2,5741,22079] 2021-11-09 03:55:36 2021-11-10 09:00:12
30 rows selected.
--//不知道是巧合还是什么原因，两边的阻塞的sid都是=5741.
SYS@XXXXX1/ORCLX> @ sid 5741
sid = 5741
SPID PID SID SERIAL# CLIENT_INFO PNAME TRACEFILE PROGRAM TERMINAL SQL_ID STATUS C50
------ ------- ---------- ---------- ----------- ------ ------------------------------------------------------------------- ------------------ -------- ------------- -------- --------------------------------------------------
17289 39 5741 14347 SMCO /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_smco_17289.trc oracle@oda1 (SMCO) UNKNOWN ACTIVE alter system kill session '5741,14347' immediate;
SYS@XXXXX1/ORCLX> @ bgx SMCO
PROGRAM MODULE ACTION SID PID SPID
---------------------------------------- ------------ ---------------- ----- ------- ------
oracle@oda1 (SMCO) KTSJ KTSJ Coordinator 5741 39 17289
--//应该是smco后台进程,不断检测导致的情况。运维没有做好相应工作，数据文件应该撑开足够的大小。
CREATE TABLESPACE PPPPPP_HHH DATAFILE
'+DATA/ORCLX/DATAFILE/PPPPPP_HHH01' SIZE 12724M AUTOEXTEND ON NEXT 20M MAXSIZE UNLIMITED,
'+DATA/ORCLX/DATAFILE/PPPPPP_HHH02' SIZE 12644M AUTOEXTEND ON NEXT 20M MAXSIZE UNLIMITED
LOGGING
ONLINE
EXTENT MANAGEMENT LOCAL AUTOALLOCATE
BLOCKSIZE 8K
SEGMENT SPACE MANAGEMENT MANUAL
FLASHBACK ON;
--//先增加数据文件大小 32G-8K = 32*1024*1024-8 = 33554424 K.
--//安全一点是慢慢增加，不是一次到位。过程略.
--//明天上班观察看看。上班观察发现，问题依旧：
--//2021-11-10 观察到的情况,没解决问题.该扩展的数据文件我已经扩展了，为什么还出现这样的情况呢?
SYS@XXXXX1/ORCLX> @ ashtop trunc(sample_time,'HH'),event,p1,p2,p3 "event like '%latch free%'" trunc(sysdate) sysdate
Total
Seconds AAS %This TRUNC_SAMPLE_TIME,' EVENT P1 P2 P3 FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------------- ---------- ---------- ---------- ---------- ------------------- -------------------
116 .0 12% | 2021-11-10 07:00:00 latch free 1611087616 517 0 2021-11-10 07:00:23 2021-11-10 07:59:56
115 .0 12% | 2021-11-10 00:00:00 latch free 1611087616 517 0 2021-11-10 00:01:25 2021-11-10 00:59:22
112 .0 12% | 2021-11-10 02:00:00 latch free 1611087616 517 0 2021-11-10 02:00:32 2021-11-10 02:59:56
111 .0 12% | 2021-11-10 03:00:00 latch free 1611087616 517 0 2021-11-10 03:00:00 2021-11-10 03:59:31
106 .0 11% | 2021-11-10 04:00:00 latch free 1611087616 517 0 2021-11-10 04:00:09 2021-11-10 04:58:54
105 .0 11% | 2021-11-10 05:00:00 latch free 1611087616 517 0 2021-11-10 05:02:04 2021-11-10 05:59:23
104 .0 11% | 2021-11-10 06:00:00 latch free 1611087616 517 0 2021-11-10 06:00:01 2021-11-10 06:59:38
91 .0 10% | 2021-11-10 01:00:00 latch free 1611087616 517 0 2021-11-10 01:00:58 2021-11-10 01:59:38
89 .0 9% | 2021-11-10 08:00:00 latch free 1611087616 517 0 2021-11-10 08:00:41 2021-11-10 08:49:04
9 rows selected.
SYS@XXXXX1/ORCLX> @ hide _spacebg
NAME DESCRIPTION DEFAULT_VALUE SESSION_VALUE SYSTEM_VALUE ISSES ISSYS_MOD
---------------------------- ----------------------------------------------------- ------------- ------------- ------------ ----- ---------
_enable_spacebg enable space management background task TRUE TRUE TRUE FALSE IMMEDIATE
_max_spacebg_msgs_percentage maximum space management interrupt message throttling TRUE 50 50 FALSE IMMEDIATE
_max_spacebg_slaves maximum space management background slaves TRUE 1024 1024 FALSE IMMEDIATE
_max_spacebg_tasks maximum space management background tasks TRUE 8192 8192 FALSE FALSE
_min_spacebg_slaves minimum space management background slaves TRUE 2 2 FALSE IMMEDIATE
_minmax_spacebg_slaves min-max space management background slaves TRUE 8 8 FALSE IMMEDIATE
_spacebg_sync_segblocks to enable/disable segmon driver TRUE TRUE TRUE TRUE IMMEDIATE
7 rows selected.
--//临时关闭这个特性。
SYS@XXXXX1/ORCLX> alter system set "_enable_spacebg"=false scope=memory;
System altered.
--//关闭后确实消失,但是打开马上出现,有点奇怪.
SYS@XXXXX1/ORCLX> alter system set "_enable_spacebg"=true scope=memory;
System altered.
SYS@XXXXX1/ORCLX> @ ashtop trunc(sample_time,'HH'),event,p1,p2,p3 "event like '%latch free%'" trunc(sysdate) sysdate
Total
Seconds AAS %This TRUNCSAMPLE_TIME,' EVENT P1 P2 P3 FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------------- ---------- ---------- ---------- ---------- ------------------- -------------------
144 .0 13% | 2021-11-11 05:00:00 latch free 1611087616 517 0 2021-11-11 05:00:20 2021-11-11 05:59:53
144 .0 13% | 2021-11-11 06:00:00 latch free 1611087616 517 0 2021-11-11 06:01:04 2021-11-11 06:59:50
129 .0 12% | 2021-11-11 04:00:00 latch free 1611087616 517 0 2021-11-11 04:00:30 2021-11-11 04:59:58
125 .0 12% | 2021-11-11 07:00:00 latch free 1611087616 517 0 2021-11-11 07:00:09 2021-11-11 07:59:42
119 .0 11% | 2021-11-11 02:00:00 latch free 1611087616 517 0 2021-11-11 02:00:45 2021-11-11 02:59:36
118 .0 11% | 2021-11-11 08:00:00 latch free 1611087616 517 0 2021-11-11 08:00:11 2021-11-11 08:51:18
104 .0 10% | 2021-11-11 03:00:00 latch free 1611087616 517 0 2021-11-11 03:00:21 2021-11-11 03:59:58
99 .0 9% | 2021-11-11 01:00:00 latch free 1611087616 517 0 2021-11-11 01:02:02 2021-11-11 01:59:59
95 .0 9% | 2021-11-11 00:00:00 latch free 1611087616 517 0 2021-11-11 00:00:01 2021-11-11 00:59:40
SYS@XXXXX1/ORCLX> @ wcy sysdate-1/24 sysdate "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
------ ---------- ------- ------ ------------------------------------------------------------------------------------------------ ------------------- -------------------
10% 14 .0 1 -> 53,14066,@2=>636,42912,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 07:54:57 2021-11-11 08:46:32
9% 12 .0 1 -> 53,14066,@2=>359,48271,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:09:14 2021-11-11 08:51:18
8% 11 .0 1 -> 53,14066,@2=>346,23425,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 07:53:20 2021-11-11 08:38:37
6% 9 .0 1 -> 3029,60358,@1=>643,2565,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:53:04 2021-11-11 08:47:46
6% 9 .0 1 -> 53,14066,@2=>335,60360,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 07:56:30 2021-11-11 08:49:44
6% 8 .0 1 -> 53,14066,@2=>1218,18526,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:00:30 2021-11-11 08:50:32
6% 8 .0 1 -> 3029,60358,@1=>633,10877,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:53:52 2021-11-11 08:46:58
6% 8 .0 1 -> 3029,60358,@1=>340,31327,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:54:38 2021-11-11 08:49:22
5% 7 .0 1 -> 3029,60358,@1=>334,5066,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:13:44 2021-11-11 08:44:37
5% 7 .0 1 -> 53,14066,@2=>619,27188,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 07:59:42 2021-11-11 08:48:56
5% 7 .0 1 -> 3029,60358,@1=>611,55630,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:55:26 2021-11-11 08:51:41
4% 6 .0 1 -> 3029,60358,@1=>640,11174,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:03:24 2021-11-11 08:35:50
4% 5 .0 1 -> 3029,60358,@1=>629,25751,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:09:43 2021-11-11 08:50:53
4% 5 .0 1 -> 53,14066,@2=>1248,24780,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:05:16 2021-11-11 08:48:56
3% 4 .0 1 -> 53,14066,@2=>1235,27336,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:05:16 2021-11-11 08:42:34
2% 3 .0 1 -> 3029,60358,@1=>934,43845,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:56:14 2021-11-11 08:38:15
2% 3 .0 1 -> 3029,60358,@1=>920,25477,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:56:14 2021-11-11 08:36:38
2% 3 .0 1 -> 3029,60358,@1=>945,8745,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 07:54:38 2021-11-11 08:35:50
1% 1 .0 1 -> ,,@=>1218,18526,@2=>latch free 2021-11-11 08:07:38 2021-11-11 08:07:38
1% 1 .0 1 -> 3029,60358,@1=>2744,30318,@1=>latch free -> ,,@=>3029,60358,@1=> 2021-11-11 08:22:27 2021-11-11 08:22:27
1% 1 .0 1 -> 3029,60358,@1=>31,26804,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:39:48 2021-11-11 08:39:48
1% 1 .0 1 -> 53,14066,@2=>3671,18541,@2=>latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 08:27:29 2021-11-11 08:27:29
1% 1 .0 1 -> 3029,60358,@1=>1539,44405,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:37:26 2021-11-11 08:37:26
1% 1 .0 1 -> 53,14066,@2=>1850,20064,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:33:03 2021-11-11 08:33:03
1% 1 .0 1 -> 53,14066,@2=>66,51514,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:15:36 2021-11-11 08:15:36
1% 1 .0 1 -> 53,14066,@2=>953,27220,@2=>latch free -> ,,@=>53,14066,@2=> 2021-11-11 08:50:32 2021-11-11 08:50:32
1% 1 .0 1 -> 934,43845,@1=>611,55630,@1=>latch free -> [idle blocker 1,934,43845 (oracle@oda1 (W00R))] 2021-11-11 08:42:12 2021-11-11 08:42:12
1% 1 .0 1 -> 53,14066,@2=>335,60360,@2=>latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 08:52:06 2021-11-11 08:52:06
28 rows selected.
--//实例1上执行：
SYS@XXXXX1/ORCLX> @ bgx SMCO
PROGRAM MODULE ACTION SID PID SPID
-------------------------- ------------ ---------------- ----- ------- ------
oracle@oda1 (SMCO) KTSJ KTSJ Coordinator 3029 450 89595
--//实例2上执行：
SYS@XXXXX2/ORCLX> @ bgx SMCO
PROGRAM MODULE ACTION SID PID SPID
-------------------------- ------------ ---------------- ---- ------- ------
oracle@oda2 (SMCO) KTSJ KTSJ Coordinator 53 740 85315
--//如果你查询阻塞的sid可以发现都是W00开头的后台进程。
--//实例1上执行：
SYS@XXXXX1/ORCLX> @ bgx W00
PROGRAM MODULE ACTION SID PID SPID
------------------ ------------ ---------- ---------- ------- ------
oracle@oda1 (W000) KTSJ KTSJ Slave 1822 486 89598
oracle@oda1 (W001) KTSJ KTSJ Slave 1824 586 89602
oracle@oda1 (W002) KTSJ KTSJ Slave 5454 738 34395
oracle@oda1 (W003) KTSJ KTSJ Slave 2430 468 89816
oracle@oda1 (W004) KTSJ KTSJ Slave 5151 677 89842
oracle@oda1 (W005) KTSJ KTSJ Slave 4566 175 44224
oracle@oda1 (W006) KTSJ KTSJ Slave 3348 191 66397
oracle@oda1 (W007) KTSJ KTSJ Slave 3332 91 66407
oracle@oda1 (W008) KTSJ KTSJ Slave 2742 209 66423
oracle@oda1 (W009) KTSJ KTSJ Slave 945 203 66439
oracle@oda1 (W00A) KTSJ KTSJ Slave 5455 258 66454
oracle@oda1 (W00B) KTSJ KTSJ Slave 5769 219 66470
oracle@oda1 (W00C) KTSJ KTSJ Slave 2758 349 66588
oracle@oda1 (W00D) KTSJ KTSJ Slave 643 322 66683
oracle@oda1 (W00E) KTSJ KTSJ Slave 5154 357 66839
oracle@oda1 (W00F) KTSJ KTSJ Slave 4546 355 66869
oracle@oda1 (W00G) KTSJ KTSJ Slave 611 362 66921
oracle@oda1 (W00H) KTSJ KTSJ Slave 633 182 66933
oracle@oda1 (W00I) KTSJ KTSJ Slave 334 381 66951
oracle@oda1 (W00J) KTSJ KTSJ Slave 31 360 67055
oracle@oda1 (W00K) KTSJ KTSJ Slave 1521 385 67069
oracle@oda1 (W00L) KTSJ KTSJ Slave 629 382 67144
oracle@oda1 (W00M) KTSJ KTSJ Slave 1844 386 67168
oracle@oda1 (W00N) KTSJ KTSJ Slave 4260 394 67282
oracle@oda1 (W00O) KTSJ KTSJ Slave 5155 397 67334
oracle@oda1 (W00P) KTSJ KTSJ Slave 1834 206 67439
oracle@oda1 (W00Q) KTSJ KTSJ Slave 640 402 67456
oracle@oda1 (W00R) KTSJ KTSJ Slave 934 403 67466
oracle@oda1 (W00S) KTSJ KTSJ Slave 1232 404 67483
oracle@oda1 (W00T) KTSJ KTSJ Slave 1539 405 67498
oracle@oda1 (W00U) KTSJ KTSJ Slave 2132 407 67515
oracle@oda1 (W00V) KTSJ KTSJ Slave 2453 408 67538
oracle@oda1 (W00W) KTSJ KTSJ Slave 3050 410 67648
oracle@oda1 (W00X) KTSJ KTSJ Slave 5444 418 67766
oracle@oda1 (W00Y) KTSJ KTSJ Slave 24 420 67858
oracle@oda1 (W00Z) KTSJ KTSJ Slave 340 421 67906
36 rows selected.
SYS@XXXXX1/ORCLX> @ wcy sysdate-1/24 sysdate "event='latch free' and inst_id=1"
-- 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
------ ---------- ---------- ------ ----------------------------------------------------------------------------------------------- ------------------- -------------------
15% 12 0 1 -> 3029,60358,@1=>643,2565,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:25:37 2021-11-11 09:13:56
11% 9 0 1 -> 3029,60358,@1=>633,10877,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:35:02 2021-11-11 09:11:32
10% 8 0 1 -> 3029,60358,@1=>340,31327,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:47:46 2021-11-11 09:19:33
9% 7 0 1 -> 3029,60358,@1=>334,5066,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:26:25 2021-11-11 08:52:29
9% 7 0 1 -> 3029,60358,@1=>629,25751,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:24:48 2021-11-11 09:08:22
9% 7 0 1 -> 3029,60358,@1=>640,11174,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:21:39 2021-11-11 09:12:20
6% 5 0 1 -> 3029,60358,@1=>920,25477,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:36:38 2021-11-11 09:10:44
6% 5 0 1 -> 3029,60358,@1=>934,43845,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:38:15 2021-11-11 09:14:44
5% 4 0 1 -> 3029,60358,@1=>611,55630,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:27:13 2021-11-11 09:01:12
4% 3 0 1 -> 3029,60358,@1=>945,8745,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:35:50 2021-11-11 09:12:20
4% 3 0 1 -> 3029,60358,@1=>31,26804,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:39:48 2021-11-11 09:10:44
4% 3 0 1 -> 3029,60358,@1=>1521,39029,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:56:26 2021-11-11 09:04:25
1% 1 0 1 -> 3029,60358,@1=>2744,30318,@1=>latch free -> ,,@=>3029,60358,@1=> 2021-11-11 08:22:27 2021-11-11 08:22:27
1% 1 0 1 -> 3029,60358,@1=>1818,64479,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:58:51 2021-11-11 08:58:51
1% 1 0 1 -> 3029,60358,@1=>1539,44405,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 08:37:26 2021-11-11 08:37:26
1% 1 0 1 -> 3029,60358,@1=>24,6540,@1=>latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 09:11:32 2021-11-11 09:11:32
1% 1 0 1 -> 2453,5139,@1=>1824,53545,@1=>latch free -> [idle blocker 1,2453,5139 (oracle@oda1 (W00V))] 2021-11-11 08:58:03 2021-11-11 08:58:03
1% 1 0 1 -> 934,43845,@1=>611,55630,@1=>latch free -> [idle blocker 1,934,43845 (oracle@oda1 (W00R))] 2021-11-11 08:42:12 2021-11-11 08:42:12
1% 1 0 1 -> ,,@=>1824,53545,@1=>latch free 2021-11-11 08:57:15 2021-11-11 08:57:15
19 rows selected.
--//顺便选取其中几个sid看看。
SYS@XXXXX1/ORCLX> @ sid 643,633,340,334,629,640,920,934,611,945
sid = 643,633,340,334,629,640,920,934,611,945
SPID PID SID SERIAL# CLIENT_INFO PNAME TRACEFILE PROGRAM TERMINAL SQL_ID STATUS C50
------ ------- ---------- ---------- -------------------- ------ ------------------------------------------------------------------- ------------------ ------------ ------------- -------- --------------------------------------------------
66933 182 633 10877 W00H /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00h_66933.trc oracle@oda1 (W00H) UNKNOWN ACTIVE alter system kill session '633,10877' immediate;
66439 203 945 8745 W009 /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w009_66439.trc oracle@oda1 (W009) UNKNOWN ACTIVE alter system kill session '945,8745' immediate;
66683 322 643 2565 W00D /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00d_66683.trc oracle@oda1 (W00D) UNKNOWN ACTIVE alter system kill session '643,2565' immediate;
66921 362 611 55630 W00G /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00g_66921.trc oracle@oda1 (W00G) UNKNOWN ACTIVE alter system kill session '611,55630' immediate;
66951 381 334 5066 W00I /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00i_66951.trc oracle@oda1 (W00I) UNKNOWN ACTIVE alter system kill session '334,5066' immediate;
67144 382 629 25751 W00L /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00l_67144.trc oracle@oda1 (W00L) UNKNOWN ACTIVE alter system kill session '629,25751' immediate;
67456 402 640 11174 W00Q /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00q_67456.trc oracle@oda1 (W00Q) UNKNOWN ACTIVE alter system kill session '640,11174' immediate;
67466 403 934 43845 W00R /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00r_67466.trc oracle@oda1 (W00R) UNKNOWN ACTIVE alter system kill session '934,43845' immediate;
67906 421 340 31327 W00Z /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w00z_67906.trc oracle@oda1 (W00Z) UNKNOWN ACTIVE alter system kill session '340,31327' immediate;
67939 423 920 25477 W010 /u01/app/oracle/diag/rdbms/ORCLX/ORCLX1/trace/ORCLX1_w010_67939.trc oracle@oda1 (W010) UNKNOWN ACTIVE alter system kill session '920,25477' immediate;
10 rows selected.
--//可以发现oracle后台进程在相互阻塞，我估计某种条件下激活oracle的bug导致这样的情况。
--//换一个查询方式也可以验证我的判断。
SYS@XXXXX1/ORCLX> @ tpt/ash/ash_wait_chains username||':'||program2||event2 "event='latch free'" trunc(sysdate) sysdate
-- 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
------ ---------- ---------- ------ ----------------------------------------------------------------------------- ------------------- -------------------
26% 311 0 10 -> SYS:(Wnnn) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 00:00:01 2021-11-11 09:32:30
7% 83 0 1 -> SYS:(WnnU) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 00:00:50 2021-11-11 09:34:06
7% 79 0 4 -> SYS:(Wnnn) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:01:46 2021-11-11 09:32:14
6% 72 0 1 -> SYS:(WnnG) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:06:32 2021-11-11 09:29:53
6% 66 0 1 -> SYS:(WnnI) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:03:22 2021-11-11 09:22:43
5% 63 0 1 -> SYS:(WnnZ) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:12:48 2021-11-11 09:33:51
5% 63 0 1 -> SYS:(WnnV) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 00:27:48 2021-11-11 09:26:56
5% 60 0 1 -> SYS:(WnnD) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:26:17 2021-11-11 09:13:56
4% 53 0 1 -> SYS:(WnnL) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:07:20 2021-11-11 09:27:28
4% 53 0 1 -> SYS:(WnnQ) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:05:47 2021-11-11 09:31:26
4% 50 0 1 -> SYS:(WnnH) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:21:31 2021-11-11 09:21:55
3% 35 0 1 -> SYS:(WnnO) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 00:55:43 2021-11-11 09:22:10
3% 33 0 1 -> SYS:(WnnR) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:22:19 2021-11-11 09:24:19
3% 30 0 1 -> SYS:(WnnM) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 03:28:14 2021-11-11 09:12:39
1% 13 0 8 -> SYS:(Wnnn) latch free 2021-11-11 02:06:19 2021-11-11 08:57:15
1% 12 0 1 -> SYS:(WnnS) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:10:33 2021-11-11 07:25:15
1% 10 0 1 -> SYS:(WnnJ) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:02:34 2021-11-11 09:10:44
1% 10 0 1 -> SYS:(Wnnn) latch free -> SYS:(SMCO) ON CPU 2021-11-11 06:22:32 2021-11-11 08:22:27
1% 6 0 1 -> SYS:(WnnM) latch free 2021-11-11 01:04:27 2021-11-11 09:19:01
0% 5 0 1 -> SYS:(WnnT) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 01:19:32 2021-11-11 08:37:26
0% 5 0 1 -> SYS:(WnnK) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 01:08:24 2021-11-11 09:04:25
0% 5 0 1 -> SYS:(WnnC) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 04:44:29 2021-11-11 06:29:58
0% 5 0 1 -> SYS:(WnnY) latch free -> [idle blocker 1,3029,60358 (oracle@oda1 (SMCO))] 2021-11-11 00:14:24 2021-11-11 09:11:32
0% 4 0 1 -> SYS:(WnnO) latch free 2021-11-11 01:20:20 2021-11-11 09:33:18
0% 4 0 1 -> SYS:(WnnD) latch free 2021-11-11 03:24:58 2021-11-11 03:54:08
0% 4 0 1 -> SYS:(WnnN) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 04:58:46 2021-11-11 08:33:03
0% 3 0 1 -> SYS:(WnnH) latch free -> [idle blocker 2,53,14066 (oracle@oda2 (SMCO))] 2021-11-11 01:08:24 2021-11-11 08:27:29
0% 3 0 1 -> SYS:(WnnH) latch free 2021-11-11 00:19:10 2021-11-11 03:29:43
0% 3 0 1 -> SYS:(WnnS) latch free 2021-11-11 00:00:13 2021-11-11 07:29:13
0% 2 0 1 -> SYS:(WnnQ) latch free 2021-11-11 02:50:49 2021-11-11 03:13:50
--//可以发现oracle后台进程在相互阻塞，我估计某种条件下激活oracle的bug导致这样的情况。
--//我个人认为可能与我们应用磁盘空间需求很大存在某种联系。
--//随便看一个awr报表，Segments by DB Blocks Changes靠前都是如下：
Segments by DB Blocks Changes
% of Capture shows % of DB Block Changes for each top segment compared
with total DB Block Changes for all segments captured by the Snapshot
When ** MISSING ** occurs, some of the object attributes may not be available
Owner Tablespace Name Object Name Subobject Name Obj. Type Obj# Dataobj# DB Block Changes % of Capture
SYS SYSAUX EXP_STAT$ TABLE 726 726 33,248 23.72
pppppp_HIS pppppp_HIS CA_SIGN TABLE 104049 112819 18,608 13.28
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
SYS SYSTEM USER$ TABLE 22 10 6,576 4.69
SYS@XXXXX1/ORCLX> @@ desc pppppp_his.CA_SIGN
Name Null? Type
------------------------------- -------- ----------------------------
1 JLXH NOT NULL NUMBER(18)
2 TABLENAME VARCHAR2(30)
3 TABLEKEYNAME VARCHAR2(30)
4 TABLEKEYVALUE VARCHAR2(20)
5 STYPE NUMBER(1)
6 CZGH VARCHAR2(10)
7 CZSJ DATE
8 IFTSA NUMBER(1)
9 CERTID VARCHAR2(100)
10 BASE64CERTID VARCHAR2(2000)
11 CERTSN VARCHAR2(50)
12 CERTENTITY VARCHAR2(50)
13 TSINFO_TIME VARCHAR2(30)
14 PLAINTEXT BLOB
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
15 SIGNDATA BLOB
16 TSRESPDATA BLOB
17 TSREQDATA BLOB
--//后面有4个blob字段。
SYS@XXXXX1/ORCLX> select * from V$SEGMENT_STATISTICS where statistic_name='space allocated' order by value desc fetch first 3 rows only;
OWNER OBJECT_NAME SUBOBJECT_ TABLESPACE_NAME TS# OBJ# DATAOBJ# OBJECT_TYPE STATISTIC_NAME STATISTIC# VALUE CON_ID
---------- -------------------------- ---------- --------------- ---- ------ ---------- ------------------ --------------- ---------- ---------- ------
pppppp_HIS CA_SIGN pppppp_HIS 7 104049 112819 TABLE space allocated 20 335544320 0
pppppp_HIS SYS_LOB0000104049C00014$$ pppppp_HIS 7 104050 112818 LOB space allocated 20 201326592 0
pppppp_EMR SYS_LOB0000109695C00002$$ pppppp_EMR 8 109696 125167 LOB space allocated 20 67108864 0
--//可以看出前面2个段space allocated增加很大。SYS_LOB0000104049C00014$$ 说明是表CA_SIGN 的PLAINTEXT blog段。
SYS@XXXXX1/ORCLX> @ sosiz pppppp_his CA_SIGN
**********************************
Table Level 参数 schema tablename
**********************************
Table Number Empty Average Chain Average Global User Sample
Name of Rows Blocks Blocks Space Count Row Len Stats Stats Size LAST_ANALYZED
--------------- -------------- ------------ ------------ -------- -------- -------- ------ ------ -------------- -------------------
CA_SIGN 2,021,065 908,590 39 0 0 2,929 YES NO 2,021,065 2021-11-09 22:02:25
.....
--//11月9号才刚刚分析,也就是V$SEGMENT_STATISTICS记录是昨天晚上10点之后的值，单位字节，335544320/1024/1024 = 320M.好像是。
--// 201326592/1024/1024 = 192M.这种情况导致大小是按照前面定义next=20M还是64M，我不是很清楚。总之在这样的情况激活了某种bug。
--//无法重启验证我的判断，先暂时设置"_enable_spacebg"=false。
SYS@XXXXX1/ORCLX> alter system set "_enable_spacebg"=false scope=memory;
System altered.
--//总之遇到一些细节问题，要仔细探究，不要轻言放弃。