[20241127]奇葩的问题.txt

[20241127]奇葩的问题.txt --//前几天在一个小表40M上建立在线索引，等很久我检查发现enq TX row锁，发现用户的事务很久没有提交，最后被取消操作，导致 --//SYS_JOURNAL开头IOT表留在数据库里面，我也没管它，做其他事情，以为又是防水墙导致的问题，因为在线建立索引要建立一张IOT --//表，在结束时删除该IOT表，也许防水墙设计有问题禁止了drop操作，快下班再次尝试，我想反正表很小，这次我直接建立。但是还 --//是挂起，只能取消操作，不然影响正常业务。我检查发现还是有一些事务没有提交导致的问题，今天探究看看。 1.环境: XXXXXX> @ver1 PORT_STRING                    VERSION        BANNER ------------------------------ -------------- -------------------------------------------------------------------------------- x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production $ cat ftq.sql column UNDO_SQL format a100 column LOGON_USER format a10 column OPERATION format a10 column TABLE_NAME format a20 column TABLE_owner format a10 column START_SCN format 999999999999 --//alter database add supplemental log data; select * from flashback_transaction_query where xid=hextoraw('&&1'); --//注意：要打开最小附加日志，视图flashback_transaction_query才会有输出，生产系统没有这个问题。 2.分析: XXXXXX> @ trans        SID    SERIAL# USERNAME    TADDR            SES_ADDR          USED_UBLK  USED_UREC    0xFLAG STATUS  STATUS2          START_DATE              XIDUSN    XIDSLOT     XIDSQN XID              PRV_XID          PTX_XID ---------- ---------- ----------- ---------------- ---------------- ---------- ---------- --------- ------- ---------------- ------------------- ---------- ---------- ---------- ---------------- ---------------- ----------------       2262      43061 PPPPPP_EMR  0000000655659A68 0000000679BB3698          1          3      1E03 ACTIVE  ACTIVE           2024-11-27 08:54:51          3          6    5390214 03000600863F5200 0000000000000000 0000000000000000       7940      42629 PPPPPP_EMR  000000064F0DAFD8 000000068E577650          1          3      1E03 ACTIVE  ACTIVE           2024-11-27 08:51:47         28         24    5161268 1C00180034C14E00 0000000000000000 0000000000000000       1983        399 PPPPPP_HIS  0000000648430BB8 000000068DB6E670          1         10    401E03 ACTIVE  ACTIVE           2024-11-27 09:04:40          8         31   11017005 08001F002D1BA800 0000000000000000 0000000000000000       3395       2111 PPPPPP_HIS  0000000648558EA8 0000000689DBCA78          1          3      1E03 ACTIVE  ACTIVE           2024-11-26 15:05:27         24          3    6637017 18000300D9456500 0000000000000000 0000000000000000        868      62613 PPPPPP_HIS  0000000666DD0978 000000068D97C7D0          8        403      1E03 ACTIVE  ACTIVE           2024-11-27 09:06:13         27          9    7719731 1B00090033CB7500 0000000000000000 0000000000000000       3416       9373 PPPPPP_HIS  00000006559E1EB0 0000000689DB37D8          1         11    401E03 ACTIVE  ACTIVE           2024-11-27 08:48:42         10         12   35330160 0A000C0070181B02 0000000000000000 0000000000000000 6 rows selected. --//竟然还有启动2024-11-26 15:05:27的事务，没有提交。 --//xid = 03000600863F5200 --//提交前. XXXXXX> @ ftq 03000600863F5200 XID                  START_SCN START_TIMESTAMP     COMMIT_SCN COMMIT_TIMESTAMP    LOGON_USER UNDO_CHANGE# OPERATION  TABLE_NAME           TABLE_OWNE ROW_ID              UNDO_SQL ---------------- ------------- ------------------- ---------- ------------------- ---------- ------------ ---------- -------------------- ---------- ------------------- ---------------------------------------------------------------------------------------------------- 03000600863F5200   53480906458 2024-11-27 08:54:48                                PPPPPP_EMR            1 INSERT     EMR_BL_BLSY          PPPPPP_EMR AAAZK2AAbAANcZEABD  delete from "PPPPPP_EMR"."EMR_BL_BLSY" where ROWID = 'AAAZK2AAbAANcZEABD'; 03000600863F5200   53480906458 2024-11-27 08:54:48                                PPPPPP_EMR            2 BEGIN --//提交后. XXXXXX> @ ftq 03000600863F5200 XID                  START_SCN START_TIMESTAMP        COMMIT_SCN COMMIT_TIMESTAMP    LOGON_USER UNDO_CHANGE# OPERATION  TABLE_NAME           TABLE_OWNE ROW_ID              UNDO_SQL ---------------- ------------- ------------------- ------------- ------------------- ---------- ------------ ---------- -------------------- ---------- ------------------- ------------------------------------------------------------------------------------------ 03000600863F5200   53480906458 2024-11-27 08:54:48   53481936730 2024-11-27 09:16:42 PPPPPP_EMR            1 INSERT     EMR_BL_BLSD          PPPPPP_EMR AAAW6SAAiAAA83UABM  delete from "PPPPPP_EMR"."EMR_BL_BLSD" where ROWID = 'AAAW6SAAiAAA83UABM'; 03000600863F5200   53480906458 2024-11-27 08:54:48   53481936730 2024-11-27 09:16:42 PPPPPP_EMR            2 INSERT     EMR_BL_BLSY          PPPPPP_EMR AAAZK2AAbAANcZEABD  delete from "PPPPPP_EMR"."EMR_BL_BLSY" where ROWID = 'AAAZK2AAbAANcZEABD'; 03000600863F5200   53480906458 2024-11-27 08:54:48   53481936730 2024-11-27 09:16:42 PPPPPP_EMR            3 BEGIN --//很明显从时间上可以判断是别的事务带着前面的事务提交的. --//注意1个细节，0xFLAG=401E03，我在21c下测试，有关dblink的事务前面出现0x42，我猜测0x40是与dblink相关的事务（也许是版本 --//的不同,有空在11g下验证看看) --//当我仔细反复观察后，可以确定开发在事务结束时没有写提交，而且不是1处，出现多处，真是奇葩啊，真不知道那个学校毕业的， --//更可怕的是我估计这个问题存在我们系统很久了。没有一个人静下心来定位这个问题，另外我在想为什么总院也存在这个问题，没有 --//发现，也许总院的业务比分院要忙，很快其他事务顺带就提交了,我给忽略了。 XXXXXX> @ ashtop sql_id "event='enq: TX - row lock contention'" &day     Total                                                                         Distinct Distinct    Distinct   Seconds     AAS %This   SQL_ID        FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1 --------- ------- ------- ------------- ------------------- ------------------- ---------- -------- -----------      2371      .0   77% | ar1x8j3n0860w 2024-11-26 15:31:53 2024-11-26 17:32:32          3     2371           3       284      .0    9% | 96sa2x3huz9qm 2024-11-26 15:53:26 2024-11-26 16:55:32          2      284           2       243      .0    8% | 881t6c48ms7db 2024-11-26 16:20:06 2024-11-26 16:27:41          3      243           3       119      .0    4% | gwnc60f55knbz 2024-11-26 17:11:43 2024-11-27 08:56:38          2      119           2        39      .0    1% | 5kkc977qkg1bc 2024-11-26 11:19:08 2024-11-26 11:19:46          1       39           1        21      .0    1% | btrp9hta6jutp 2024-11-26 11:21:55 2024-11-26 11:22:15          1       21           1 6 rows selected. --//可想得知，怪不得需要经常解锁，无语!! --//另外给开发一个小小建议做dblink相关查询完成后最后加入1个提交，不然trans.sql脚本的输出一直看到。