[20260416]奇怪的latch free等待事件2(buffer busy waits).txt

--//继续前面的分析,继续探究遇到buffer busy waits等待事件的情况：
SYS@book> @ ashtop event 1=1 trunc(sysdate)+16/24+20/1440+16/86400 trunc(sysdate)+16/24+21/1440+14/86400
    Total                                                                                       Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                       FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- --------------------------- ------------------- ------------------- ---------- -------- -----------
     1084    18.7   58% |                             2026-04-16 16:20:16 2026-04-16 16:21:13        883       56         934
      310     5.3   17% | latch free                  2026-04-16 16:20:18 2026-04-16 16:21:12        307       32         310
      106     1.8    6% | buffer busy waits           2026-04-16 16:20:23 2026-04-16 16:21:10        106       23         106
       82     1.4    4% | latch: undo global data     2026-04-16 16:20:22 2026-04-16 16:21:13         82        9          82
       63     1.1    3% | log file parallel write     2026-04-16 16:20:17 2026-04-16 16:21:13          1       45          45
       50      .9    3% | LGWR any worker group       2026-04-16 16:20:18 2026-04-16 16:21:13          1       50          50
       38      .7    2% | cursor: pin S               2026-04-16 16:20:19 2026-04-16 16:21:10          1       10          10
       25      .4    1% | LGWR worker group ordering  2026-04-16 16:20:19 2026-04-16 16:21:12          1       25          25
       18      .3    1% | latch: enqueue hash chains  2026-04-16 16:20:21 2026-04-16 16:21:10         18        7          18
       15      .3    1% | latch: redo allocation      2026-04-16 16:20:23 2026-04-16 16:21:11          8        7          11
       14      .2    1% | latch: cache buffers chains 2026-04-16 16:20:56 2026-04-16 16:21:09         14        4          14
       14      .2    1% | log file switch completion  2026-04-16 16:20:32 2026-04-16 16:20:32         14        1          14
       12      .2    1% | log file sync               2026-04-16 16:20:17 2026-04-16 16:21:13          1        5           5
       11      .2    1% | LGWR wait for redo copy     2026-04-16 16:20:20 2026-04-16 16:21:07          1       11          11
       10      .2    1% | db file async I/O submit    2026-04-16 16:20:33 2026-04-16 16:21:11          1       10          10
        4      .1    0% | latch: redo copy            2026-04-16 16:20:35 2026-04-16 16:21:06          4        3           4
        2      .0    0% | control file parallel write 2026-04-16 16:20:32 2026-04-16 16:20:39          1        2           2
        1      .0    0% | LGWR all worker groups      2026-04-16 16:20:34 2026-04-16 16:20:34          1        1           1
        1      .0    0% | direct path write           2026-04-16 16:21:05 2026-04-16 16:21:05          1        1           1
        1      .0    0% | enq: SQ - contention        2026-04-16 16:20:16 2026-04-16 16:20:16          1        1           1
        1      .0    0% | latch: redo writing         2026-04-16 16:20:23 2026-04-16 16:20:23          1        1           1
21 rows selected.
--//接着看buffer busy waits等待事件。

SYS@book> @ ev_namezpr "^buffer busy waits$"
==============================
EVENT#                        : 129
EVENT_ID                      : 2161531084
NAME                          : buffer busy waits
PARAMETER1                    : file#
PARAMETER2                    : block#
PARAMETER3                    : class#
WAIT_CLASS_ID                 : 3875070507
WAIT_CLASS#                   : 4
WAIT_CLASS                    : Concurrency
DISPLAY_NAME                  : buffer busy waits
CON_ID                        : 0
PL/SQL procedure successfully completed.

SYS@book> @ ashtop sql_id,p1,p2,p3  "event='buffer busy waits'"  trunc(sysdate)+16/24+20/1440+16/86400 trunc(sysdate)+16/24+21/1440+14/86400
    Total                                                                                                          Distinct Distinct    Distinct
  Seconds     AAS %This   SQL_ID                P1         P2         P3 FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------- ---------- ---------- ---------- ------------------- ------------------- ---------- -------- -----------
       16      .3   15% | 1q3n0uxkhyp0m         21        192         25 2026-04-16 16:20:26 2026-04-16 16:21:10         16       13          16
       16      .3   15% | 1q3n0uxkhyp0m         21        272         35 2026-04-16 16:20:23 2026-04-16 16:21:10         16       12          16
       10      .2    9% | 1q3n0uxkhyp0m         21      38656         37 2026-04-16 16:20:32 2026-04-16 16:21:10         10       10          10
        8      .1    8% | 1q3n0uxkhyp0m         21        128         17 2026-04-16 16:20:26 2026-04-16 16:21:10          8        8           8
        8      .1    8% | 1q3n0uxkhyp0m         21        144         19 2026-04-16 16:20:30 2026-04-16 16:21:06          8        7           8
        8      .1    8% | 1q3n0uxkhyp0m         21        176         23 2026-04-16 16:20:30 2026-04-16 16:21:03          8        8           8
        8      .1    8% | 1q3n0uxkhyp0m         21      38672         39 2026-04-16 16:20:30 2026-04-16 16:21:10          8        8           8
        5      .1    5% | 1q3n0uxkhyp0m         21        208         27 2026-04-16 16:20:30 2026-04-16 16:21:06          5        5           5
        5      .1    5% | 1q3n0uxkhyp0m         21        224         29 2026-04-16 16:20:23 2026-04-16 16:21:03          5        5           5
        5      .1    5% | 1q3n0uxkhyp0m         21        232         41 2026-04-16 16:20:32 2026-04-16 16:21:10          5        5           5
        5      .1    5% | 1q3n0uxkhyp0m         21        240         31 2026-04-16 16:20:26 2026-04-16 16:20:46          5        5           5
        5      .1    5% | 1q3n0uxkhyp0m         21        256         33 2026-04-16 16:20:32 2026-04-16 16:21:10          5        5           5
        4      .1    4% | 1q3n0uxkhyp0m         21        160         21 2026-04-16 16:20:32 2026-04-16 16:21:06          4        4           4
        3      .1    3% | 1q3n0uxkhyp0m         21        304         43 2026-04-16 16:20:23 2026-04-16 16:20:46          3        3           3
14 rows selected.

SYS@book> @ dbfile 21
FILELIST
------------------------------------------------
    21  /u01/oradata/BOOK/book01p/undotbs01.dbf
--//对应undo数据文件。
--//看看这些块对应时那些块。
192,272,38656,128,144,176,38672,208,224,232,240,256,160,304

SYS@book01p> @ find_objz "file_id=21 and block_id in (192,272,38656,128,144,176,38672,208,224,232,240,256,160,304)" '' '' 1 ''
FILE_ID BLOCK_ID   END_ID+1  BLOCKS SEGMENT_TYPE    OWNER SEGMENT_NAME          EXTENT_ID  BYTES TABLESPACE_NAME RELATIVE_FNO SEGTSN SEGRFN SEGBID
------- -------- ---------- ------- --------------- ----- --------------------- --------- ------ --------------- ------------ ------ ------ ------
     21      128        136       8 TYPE2 UNDO      SYS   _SYSSMU1_274027410$           0  65536 UNDOTBS1                  21      2     21    128
     21      144        152       8 TYPE2 UNDO      SYS   _SYSSMU2_3565078997$          0  65536 UNDOTBS1                  21      2     21    144
     21      160        168       8 TYPE2 UNDO      SYS   _SYSSMU3_69012697$            0  65536 UNDOTBS1                  21      2     21    160
     21      176        184       8 TYPE2 UNDO      SYS   _SYSSMU4_2342735378$          0  65536 UNDOTBS1                  21      2     21    176
     21      192        200       8 TYPE2 UNDO      SYS   _SYSSMU5_3418129456$          0  65536 UNDOTBS1                  21      2     21    192
     21      208        216       8 TYPE2 UNDO      SYS   _SYSSMU6_1620452908$          0  65536 UNDOTBS1                  21      2     21    208
     21      224        232       8 TYPE2 UNDO      SYS   _SYSSMU7_3959750909$          0  65536 UNDOTBS1                  21      2     21    224
     21      232        240       8 TYPE2 UNDO      SYS   _SYSSMU13_3507179944$         0  65536 UNDOTBS1                  21      2     21    232
     21      240        248       8 TYPE2 UNDO      SYS   _SYSSMU8_4211447069$          0  65536 UNDOTBS1                  21      2     21    240
     21      256        264       8 TYPE2 UNDO      SYS   _SYSSMU9_4020648726$          0  65536 UNDOTBS1                  21      2     21    256
     21      272        280       8 TYPE2 UNDO      SYS   _SYSSMU10_1852731602$         0  65536 UNDOTBS1                  21      2     21    272
     21      304        312       8 TYPE2 UNDO      SYS   _SYSSMU14_2762569151$         0  65536 UNDOTBS1                  21      2     21    304
     21    38656      38664       8 TYPE2 UNDO      SYS   _SYSSMU11_3184360226$         0  65536 UNDOTBS1                  21      2     21  38656
     21    38672      38680       8 TYPE2 UNDO      SYS   _SYSSMU12_1506383923$         0  65536 UNDOTBS1                  21      2     21  38672
14 rows selected.
--//注：执行脚本要在pdb下执行，不然没有结果。
--//仔细看字段BLOCK_ID和SEGBID可以发现两者相等，也就是对应undo段段头。也就是事务表。也就是大量频繁执行这类语句要产生小量
--//事务，要修改段头的事务表,有点不理解的是并发30个会话，仅仅使用14个undo段。
--//还可以执行如下确定：
SELECT * FROM dba_segments
WHERE segment_type = 'TYPE2 UNDO'
AND header_file = 21
AND header_block IN (192,272,38656,128,144,176,38672,208,224,232,240,256,160,304)
ORDER BY 8

SYS@book01p> select count(*) from dba_segments where segment_type='TYPE2 UNDO' and header_file=21;
  COUNT(*)
----------
       170
--//而我的测试环境有170个undo段。执行语句导致在这些对应的数据块存在修改事务表的情况，结果出现buffer busy waits等待事件。
--//另外写一篇latch: undo global data的情况。

--//补充测试,如果事务使用undo分散，看到的情况如下：
$ zzdate ; seq 30 | xargs -IQ -P 30 sqlplus scott/book@book01p @ m22.txt 6e4 test Q >/dev/null ; zzdate
trunc(sysdate)+17/24+05/1440+14/86400 1776416714.255784034
trunc(sysdate)+17/24+06/1440+11/86400 1776416771.396182176

SCOTT@book01p> Select method,count(*),round(avg(TIME_ELA2-TIME_ELA1),0),sum(TIME_ELA2-time_ela1) from scott.job_times group by method order by 1 ;
METHOD                 COUNT(*) ROUND(AVG(TIME_ELA2-TIME_ELA1),0) SUM(TIME_ELA2-TIME_ELA1)
-------------------- ---------- --------------------------------- ------------------------
test                         30                              5447                   163422

SYS@book01p> @ ashtop event 1=1 trunc(sysdate)+17/24+05/1440+14/86400 trunc(sysdate)+17/24+06/1440+11/86400
    Total                                                                                                      Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                                      FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
      908    15.9   56% |                                            2026-04-17 17:05:15 2026-04-17 17:06:10        740       55         790
      353     6.2   22% | latch free                                 2026-04-17 17:05:16 2026-04-17 17:06:10        350       37         353
      210     3.7   13% | latch: undo global data                    2026-04-17 17:05:17 2026-04-17 17:06:02        210       20         210
       62     1.1    4% | latch: enqueue hash chains                 2026-04-17 17:05:17 2026-04-17 17:06:08         62        9          62
       34      .6    2% | cursor: pin S                              2026-04-17 17:05:19 2026-04-17 17:06:09          1       13          13
       30      .5    2% | log file switch (checkpoint incomplete)    2026-04-17 17:05:38 2026-04-17 17:05:38         30        1          30
        9      .2    1% | latch: cache buffers chains                2026-04-17 17:05:40 2026-04-17 17:05:56          9        2           9
        9      .2    1% | latch: redo allocation                     2026-04-17 17:05:16 2026-04-17 17:05:24          9        2           9
        8      .1    0% | log file switch completion                 2026-04-17 17:06:03 2026-04-17 17:06:03          8        1           8
        5      .1    0% | log file sync                              2026-04-17 17:05:14 2026-04-17 17:06:10          1        3           3
        1      .0    0% | latch: redo copy                           2026-04-17 17:05:24 2026-04-17 17:05:24          1        1           1
11 rows selected.
--//这样看不到buffer busy waits等待事件。不过latch: enqueue hash chains出现在第3.

SYS@book01p> @ ev_namezpr 'latch: enqueue hash chains'
==============================
EVENT#                        : 604
EVENT_ID                      : 1847483002
NAME                          : latch: enqueue hash chains
PARAMETER1                    : address
PARAMETER2                    : number
PARAMETER3                    : why
WAIT_CLASS_ID                 : 1893977003
WAIT_CLASS#                   : 0
WAIT_CLASS                    : Other
DISPLAY_NAME                  : latch: enqueue hash chains
CON_ID                        : 0
PL/SQL procedure successfully completed.

SYS@book01p> @ ashtop event,p1raw,p2 "event='latch: enqueue hash chains'" trunc(sysdate)+17/24+05/1440+14/86400 trunc(sysdate)+17/24+06/1440+11/86400
    Total                                                                                                                                   Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                                      P1RAW                     P2 FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
       26      .5   42% | latch: enqueue hash chains                 000000007C6E6620          54 2026-04-17 17:05:41 2026-04-17 17:06:08         26        2          26
       18      .3   29% | latch: enqueue hash chains                 000000007C6E6580          54 2026-04-17 17:05:17 2026-04-17 17:06:06         18        4          18
       12      .2   19% | latch: enqueue hash chains                 000000007C6E64E0          54 2026-04-17 17:05:50 2026-04-17 17:05:52         12        2          12
        6      .1   10% | latch: enqueue hash chains                 000000007C6E6440          54 2026-04-17 17:05:58 2026-04-17 17:05:58          6        1           6

SYS@book01p> @ la 000000007C6E6620
ADDR                 LATCH#   CHLD NAME                                                GETS      IGETS     MISSES    IMISSES   SPINGETS     SLEEPS  WAIT_TIME
---------------- ---------- ------ --------------------------------------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000007C6E6620         54      4 enqueue hash chains                             10349960          2      19949          0      15343       4625  364052381

SYS@book01p> @ col_list v$latch_children name|^gets

SELECT
 name
,gets
FROM v$latch_children


SYS@book01p> 999 where name='enqueue hash chains' ;
SYS@book01p> /

NAME                                           GETS
---------------------------------------- ----------
enqueue hash chains                        10350002
enqueue hash chains                        10784363
enqueue hash chains                        11096498
enqueue hash chains                        10292849