一 、故障描述

2024/03/20 16:30    客户反馈，业务在 2024-03-19 14:48到 2024-03-19 14:50之间的一条简单的 insert语句正常 0.01秒能完成，但是确实也出现了执行 30S的情况。

SQL_ID： 2unh8qb6u3rrz 语句如下： insert into XXX values (:s1 ,:s2 ,:s3 ,:s4 ,:s5 ,:s6 ,:s7 ,:s8 ,:s9 ,:s10 ,:s11 ,:s12 ,:s13 ,:s14 ,:s15 ,:s16 ,:s17 ,:s18 ,:s19 ,:s20 ,:s21 ,:s22 ,:s23 ,:s24 ,:s25 ,:s26 ,:s27 ,:s28 ,:s29 ,:s30 ,:s31 ,:s32 ,:s33 ,:s34 ,:s35 ,:s36 ,:s37 ,:s38 ,:s39 ,:s40 ,:s41 ,:s42 ,:s43 ,:s44 ,:s45 ,:s46 ,:s47 ,:s48 ,:s49 ,:s50 ,:s51 ,:s52 ,:s53 ,:s54 ,:s55 ,:s56 ,:s57 )；

2024/03/21 09:30 与业务确认，业务日志中打印了执行 2条 insert SQL共花费了 30S，该 SQL的表为 A,B表每天晚上会进行 truncate 操作。白天没有 DDL操作

二、根因分析

2.1、整体数据库压力

问题时间段前后，数据库整体压力不大，不是全局因素导致的问题。另外也并没有出现其他业务的性能降低，只有 insert的单业务中的极小一次业务出现慢。

2.2、业务量

业务反馈，整体压力比较平均，不存在问题时间点有较大的 insert量。检查数据库每个快照（ 15分钟一个快照）的该 SQL的执行次数如下，从整体的量来说， 16时 48分到 16时 50分的那个快照内执行次数有 60463次，相较于其他没有明显的突变，前面 14： 30的快照有 62121次也没并出现问题。所以单纯从总量上来看，没有突增。

但是快照内每分每秒的执行次数是否平均，由于 ORACLE没有更细粒度的数据，所以无法准确看到那 2分钟是不是特别集中的有 insert。

2.3、数据库日志

2.3.1、 Alert 日志

  从数据库 alert日志中发现问题时间在 14:48:50秒到 14:49:25段刚好有一些如下信息，问题时间段前后很长一段时间段都没有这些信息，总体可以认为是热点块， ORACLE对这种信息未定位为错误，只是一种打印信息，为了不引起误解，会在后续版本取消。不能说有问题，但是也反应出这个时间点是有热块。另外时间继续拉长，日志也会有一些类似如下的信息，但没有业务反馈有问题。

2024-03-19T14:15:05.848654+08:00

KQR: cid  8 bucket  21212 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:18:08.268573+08:00

Thread 1 advanced to log sequence 77007 (LGWR switch),  current SCN: 537167914443

  Current log# 6 seq# 77007 mem# 0: +DATA/XXX/redo06.log

2024-03-19T14:18:09.867292+08:00

ARC1 (PID:26935658): Archived Log entry 250499 added for T-1.S-77006 ID 0xffffffffff03acc4 LAD:1

2024-03-19T14:32:41.481849+08:00

Thread 1 advanced to log sequence 77008 (LGWR switch),  current SCN: 537169389162

  Current log# 7 seq# 77008 mem# 0: +DATA/XXX/redo07.log

2024-03-19T14:32:43.164097+08:00

ARC2 (PID:27066738): Archived Log entry 250501 added for T-1.S-77007 ID 0xffffffffff03acc4 LAD:1

2024-03-19T14:44:45.531561+08:00

KQR: cid  8 bucket  11126 marked NORMAL

2024-03-19T14:46:17.599545+08:00

Thread 1 advanced to log sequence 77009 (LGWR switch),  current SCN: 537170500254

  Current log# 1 seq# 77009 mem# 0: +DATA/XXX/redo01.log

2024-03-19T14:46:19.246362+08:00

ARC3 (PID:24576570): Archived Log entry 250505 added for T-1.S-77008 ID 0xffffffffff03acc4 LAD:1

2024-03-19T14:48:50.738905+08:00

KQR: cid  8 bucket  24166 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:51.256120+08:00

KQR: cid  8 bucket  18022 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:51.269255+08:00

KQR: cid  8 bucket  17710 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:51.390486+08:00

KQR: cid  8 bucket    686 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:51.401949+08:00

KQR: cid  8 bucket  21683 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:51.484912+08:00

KQR: cid  8 bucket    460 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:51.668953+08:00

KQR: cid  8 bucket  15065 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:52.173931+08:00

KQR: cid  8 bucket  17068 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:52.469100+08:00

KQR: cid  8 bucket   4786 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:52.487672+08:00

KQR: cid  8 bucket  28759 marked HOT (kqrCreateUsingSecondaryKey)

KQR: cid  8 bucket   7236 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:52.965042+08:00

KQR: cid  8 bucket  12005 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:53.044293+08:00

KQR: cid  8 bucket  29358 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:53.159143+08:00

KQR: cid  8 bucket    702 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:48:53.269973+08:00

.......

KQR: cid  8 bucket  32391 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:49:25.403540+08:00

KQR: cid  8 bucket   6252 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:49:25.411438+08:00

KQR: cid  8 bucket   2353 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:49:25.754145+08:00

KQR: cid  8 bucket  31737 marked HOT (kqrCreateUsingSecondaryKey)

2024-03-19T14:56:16.588577+08:00

WARNING: too many parse errors, count=64880212 SQL hash=0xae09c966

PARSE ERROR: ospid=20710550, error=942 for statement:

Additional information: hd=700010b7df028b0 phd=700010b7deb8020 flg=0x100476 cisid=152 sid=152 ciuid=152 uid=152 sqlid=bddzwaar0mkb6

...Current username=XXX

...Application: pltserver@cbsapp1 (TNS V1-V3) Action:

2024-03-19T14:59:20.074266+08:00

KQR: cid  8 bucket  10879 marked NORMAL

2024-03-19T15:00:14.783816+08:00

Thread 1 advanced to log sequence 77010 (LGWR switch),  current SCN: 537171884513

  Current log# 2 seq# 77010 mem# 0: +DATA/XXX/redo02.log

2024-03-19T15:00:16.461340+08:00

ARC0 (PID:28312048): Archived Log entry 250509 added for T-1.S-77009 ID 0xffffffffff03acc4 LAD:1

2024-03-19T15:02:41.317199+08:00

KQR: cid  8 bucket   5039 marked NORMAL

2024-03-19T15:03:07.584985+08:00

2.3.2、 Diag诊断日志

从数据库诊断日志 diag日志发现 在问题时间段内，系统内部确实产生了 1个诊断日志，同时里面有 2个 select for update语句出现了 TX行锁等待。

可以发现 3个 session有堵塞关系， 9807堵塞 4365 ， 4365堵塞 5940。

会话 5940  等待了 32秒，等待事件为 enq: TX - row lock contention ，对应 SQL为：

select *  from accb_account where acct_no=:b0 for update

会话 4365 等待事件为 library cache lock，对应的 SQL为：

insert into XXX  values (:s1 ,:s2 ,:s3 ,:s4 ,:s5 ,:s6 ,:s7 ,:s8 ,:s9 ,:s10 ,:s11 ,:s12 ,:s13 ,:s14 ,:s15 ,:s16 ,:s17 ,:s18 ,:s19 ,:s20 ,:s21 ,:s22 ,:s23 ,:s24 ,:s25 ,:s26 ,:s27 ,:s28 ,:s29 ,:s30 ,:s31 ,:s32 ,:s33 ,:s34 ,:s35 ,:s36 ,:s37 ,:s38 ,:s39 ,:s40 ,:s41 ,:s42 ,:s43 ,:s44 ,:s45 ,:s46 ,:s47 ,:s48 ,:s49 ,:s50 ,:s51 ,:s52 ,:s53 ,:s54 ,:s55 ,:s56 ,:s57 )；

会话 9807 等待事件为 DLM cross inst call completion，该等待是一种分布式锁管理器的等待，来解决并发问题。对应的 SQL为：

insert into XXX  values (:s1 ,:s2 ,:s3 ,:s4 ,:s5 ,:s6 ,:s7 ,:s8 ,:s9 ,:s10 ,:s11 ,:s12 ,:s13 ,:s14 ,:s15 ,:s16 ,:s17 ,:s18 ,:s19 ,:s20 ,:s21 ,:s22 ,:s23 ,:s24 ,:s25 ,:s26 ,:s27 ,:s28 ,:s29 ,:s30 ,:s31 ,:s32 ,:s33 ,:s34 ,:s35 ,:s36 ,:s37 ,:s38 ,:s39 ,:s40 ,:s41 ,:s42 ,:s43 ,:s44 ,:s45 ,:s46 ,:s47 ,:s48 ,:s49 ,:s50 ,:s51 ,:s52 ,:s53 ,:s54 ,:s55 ,:s56 ,:s57 )

    具体日志内容如下

insert into XXX  values (:s1 ,:s2 ,:s3 ,:s4 ,:s5 ,:s6 ,:s7 ,:s8 ,:s9 ,:s10 ,:s11 ,:s12 ,:s13 ,:s14 ,:s15 ,:s16 ,:s17 ,:s18 ,:s19 ,:s20 ,:s21 ,:s22 ,:s23 ,:s24 ,:s25 ,:s26 ,:s27 ,:s28 ,:s29 ,:s30 ,:s31 ,:s32 ,:s33 ,:s34 ,:s35 ,:s36 ,:s37 ,:s38 ,:s39 ,:s40 ,:s41 ,:s42 ,:s43 ,:s44 ,:s45 ,:s46 ,:s47 ,:s48 ,:s49 ,:s50 ,:s51 ,:s52 ,:s53 ,:s54 ,:s55 ,:s56 ,:s57 )

$ cat XXX1_dia0_27263730_lws_1.trc

Trace file /oracle/app/diag/rdbms/XXX/XXX1/trace/XXX1_dia0_27263730_lws_1.trc

Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production

Version 19.16.0.0.0

Build label:    RDBMS_19.16.0.0.0DBRU_AIX.PPC64_220701

ORACLE_HOME:    /oracle/app/product/19c/db_1

System name:    AIX

Node name:      XXX1

Release:        2

Version:        7

Machine:        XXX

Instance name: XXX1

Redo thread mounted by this instance: 1

Oracle process number: 19

Unix process pid: 27263730, image: oracle@XXX1 (DIA0)

*** SESSION ID:(2300.18695) 2024-03-19T14:49:23.099443+08:00

*** CLIENT ID:() 2024-03-19T14:49:23.099453+08:00

*** SERVICE NAME:(SYS$BACKGROUND) 2024-03-19T14:49:23.099460+08:00

*** MODULE NAME:() 2024-03-19T14:49:23.099467+08:00

*** ACTION NAME:() 2024-03-19T14:49:23.099474+08:00

*** CLIENT DRIVER:() 2024-03-19T14:49:23.099480+08:00

*** TRACE FILE RECREATED AFTER BEING REMOVED ***

*** 2024-03-19T14:49:23.097286+08:00

HM: Early Warning -  Session ID 5940 serial# 48921  OS PID 62718424 (FG)

      is waiting on 'enq: TX - row lock contention' for 32 seconds,  wait id 12773822

     p1: 'name|mode'=0x54580006, p2: 'usn<<16 | slot'=0x7c0019, p3: 'sequence'=0x309f768

     Blocked by Session ID 4365  serial# 35005 on instance 1

     which is waiting on 'library cache lock' for 0 seconds

     p1: 'handle address'=0x70001003b8c1568, p2: 'lock address'=0x700010f2d0d15c8, p3: '100*mode+namespace'= 0x10003

     Final Blocker is Session ID 9807  serial# 45766 on instance 1

     which is waiting on 'DLM cross inst call completion' for 0 seconds, wait id 26426227

     p1: 'caller inst num|Opcode'=0x100000092, p2: 'cluster incarnation number'=0x10, p3: 'request identifier'=0x269917b9

 IO           

 Total  Self-         Total  Total  Outlr  Outlr  Outlr           

  Hung  Rslvd  Rslvd   Wait WaitTm   Wait WaitTm   Wait           

  Sess  Hangs  Hangs  Count   Secs  Count   Secs  Count Wait Event

------ ------ ------ ------ ------ ------ ------ ------ -----------

    28      0      0 12532693 724179     26   4192      0 enq: TX - row lock contention

 HM: Dumping Short Stack of pid[2225.62718424] (sid:5940, ser#:48921)

Short stack dump:

ksedsts()+512<-ksdxfstk()+68<-ksdxcb()+892<-sspuser()+240<-__sighandler()<-thread_wait()+556<-sskgpwwait()+56<-skgpwwait()+268<-IPRA.$ksliwat()+1968<-kslwaitctx()+204<-kjusuc()+4784<-ksipgetctxia()+4300<-IPRA.$ksqcmi()+16704<-ksqgtlctx()+4952<-ksqgelctx()+928<-ktuGetTxForXid()+348<-ktcwit1()+540<-kdddgb()+5160<-kddlkr()+320<-IPRA.$qerfuProcessFetchedRow()+628<-qerfuLockingRowProcedure()+100<-qertbFetchByRowID()+1984<-qerfuStart()+676<-selexe0()+3416<-opiexe()+21936<-kpoal8()+5424<-opiodr()+1256<-ttcpip()+636<-opitsk()+1932<-opiino()+960<-opiodr()+1256<-opidrv()+1080<-sou2o()+208<-opimai_real()+680<-ssthrdmain()+460<-main()+216<-__start()+112

HM: Current SQL: select *  from accb_account where acct_no=:b0 for update

*** 2024-03-19T14:49:25.156881+08:00

HM: Early Warning - Session ID 2190 serial# 55646 OS PID 37815064 (FG)

     is waiting on 'enq: TX - row lock contention' for 32 seconds, wait id 263398047

     p1: 'name|mode'=0x54580006, p2: 'usn<<16 | slot'=0xb10000, p3: 'sequence'=0xe34371

    Final Blocker is Session ID 14784 serial# 1872 on instance 1

     which is waiting on 'db file sequential read' for 0 seconds, wait id 265542263

     p1: 'file#'=0x1a, p2: 'block#'=0x1b42a, p3: 'blocks'=0x1

                                                     IO           

 Total  Self-         Total  Total  Outlr  Outlr  Outlr           

  Hung  Rslvd  Rslvd   Wait WaitTm   Wait WaitTm   Wait           

  Sess  Hangs  Hangs  Count   Secs  Count   Secs  Count Wait Event

------ ------ ------ ------ ------ ------ ------ ------ -----------

    28      0      0 12532693 724179     26   4192      0 enq: TX - row lock contention

HM: Dumping Short Stack of pid[530.37815064] (sid:2190, ser#:55646)

Short stack dump:

ksedsts()+512<-ksdxfstk()+68<-ksdxcb()+892<-sspuser()+240<-__sighandler()<-thread_wait()+556<-sskgpwwait()+56<-skgpwwait()+268<-IPRA.$ksliwat()+1968<-kslwaitctx()+204<-kjusuc()+4784<-ksipgetctxia()+4300<-IPRA.$ksqcmi()+16704<-ksqgtlctx()+4952<-ksqgelctx()+928<-ktuGetTxForXid()+348<-ktcwit1()+540<-kdddgb()+5160<-kddlkr()+320<-IPRA.$qerfuProcessFetchedRow()+628<-qerfuLockingRowProcedure()+100<-qertbFetchByRowID()+1984<-qerfuStart()+676<-selexe0()+3416<-opiexe()+21936<-kpoal8()+5424<-opiodr()+1256<-ttcpip()+636<-opitsk()+1932<-opiino()+960<-opiodr()+1256<-opidrv()+1080<-sou2o()+208<-opimai_real()+680<-ssthrdmain()+460<-main()+216<-__start()+112

HM: Current SQL: select *  from accb_account where acct_no=:b0 for update

4、异常等待

通过问题前后时间段的异常等待比较发现，在 14:48分开始 library cache lock从没有到 11个， 14:49分达到 46个。 同时 enq: TX - row lock contention 行锁相对之前每分钟 3个左右到 39个。另外还有少量的 row cache lock（ row cache objects 是用来保护数据字典缓存访问的 LATCH，争用通常意味着在数据字典里存在竞争）等异常等待。

对于出现的 TX锁，从 DIAG的诊断文件也可以看出，只要把堵塞他的 library cache lock解决掉，他自然也不是问题。

主要需要关注的是 library cache lock，这个等待事件比较常见的问题是涉及的对象如表有 DDL或者存储过程的编译引起的。但是检查了并发发现该表或者相关的索引有过 DDL操作（业务和 DBA都确认白天不会对该表有 DDL操作。另外该库有设置 enable_ddl_logging，相关日志中没有发现这个时间段的 DDL。），跟存储过程的编译更是没关系。

通过对多个 library cache lock的会话的 blocking_session进行分析，发现基本上 blocking session基本上都是同样的 insert 语句，很多绕来绕去也还是回到相同的 session id。另外一层一层的 blocking session找下去，发现最终都能找到一个 row cache lock的会话（对应的语句也还是 insert），但是 blocking session是空的，查看 p1值是 2，对应的字典对象是 dc_segments，跟段的扩展有关系。

通过对多个 library cache lock会话的 p3: '100*mode+namespace' 转成 16进制后，可以看到大部分都是类似如下 14e86000010003，后面 0001，和 0003分别代表 namspace 和申请的 lock mode，其中 namespace=1 代表是 TABLE/PROCEDURE， mode=3 表示 exclusive的。命名空间是 TABLE说明是 table类型的 handle上等待 latch，结合 row cache lock的字典对象等待是 dc_segments。所以认为是段的扩展导致等待。当时应该是插入较频繁，自动扩展跟不上，在扩展的过程，段 /表的信息在数据字典 dictionary cache也叫做 row cache中需要更新，所以获取了排他锁。后续其他的 insert就无法获取排他锁。

三 、解决方案

方案 1：官方建议手工对表的 extent  进行空间扩展参考如下

alter table t1 allocate extent (size 32M instance 2) ，但是 insert 是应用程序发起，手工和频繁的进行扩容显然不合理也不现实，由于这个 AB表每天晚上要进行 truncate,所以建议在 truncate后，对表进行一次手工扩容，扩容的大小建议超过每天实际生产大小。

方案 2：由于也是很偶尔才发生，所以在业务层面能否控制 insert的并发度。