[20211111]19c latch free等待时间分析.txt

[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.

--//总之遇到一些细节问题,要仔细探究,不要轻言放弃。

posted @ 2021-11-11 10:04  lfree  阅读(119)  评论(0编辑  收藏  举报