[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脚本的输出一直看到。