首页 » ORACLE 9i-23ai » How to analyze enq: TM – Contention with LogMiner？
How to analyze enq: TM – Contention with LogMiner？
最近有个客户遇到了enq: TM – contention, 确认表上有大量的FK，并且存在FK 无索引的现象，同是一张表有近60个FK ，同时子表又有几十个子表的多层FK（外键关连） , 关于这个event十多年前有记录过一个笔记”Tuning enq: TM – contention with foreign key (外键引起的队列)”, 现在这个客户也是认可是有外键缺失索引的问题，但非要找到当时的堵塞者SQL, 当然如果SQL很快如果没进ASH, 可能就不好分析了，这里使用分享logminer如何查找线索。
构造表还是参考之前的案例中的表，parent table TEAM, children table MEMB
-- session 1 delete team where id=1; 1 row deleted. -- session 2 delete team where id=2; waiting ....
分析堵塞
SQL> @ase
last_call
USERNAME SID EVENT MACHINE MODULE STATUS et SEQ# SQL_ID WAI_SECINW ROW_WAIT_OBJ# SQLTEXT BS CH# OSUSER HEX
---------- ---------- -------------------- ---------- -------------------- ------- --------- ---------- --------------- ---------- ------------- ------------------------------ ---------- ---- ---------- ----------
ANBOB 16 enq: TM - contention 11g-node2 SQL*Plus ACTIVE 51 26 155ky0vz28xuv 0:51 110073 delete team where id=2 2:391 0 oracle
SQL> SELECT sid, blocking_session, event, sql_text
FROM v$session LEFT OUTER JOIN v$sqlarea USING (sql_id)
WHERE nvl(blocking_session,sid) IN (SELECT holding_session FROM dba_blockers);
SID BLOCKING_SESSION EVENT SQL_TEXT
---------- ---------------- -------------------- ------------------------------
391 SQL*Net message from
16 391 enq: TM - contention delete team where id=2
SQL> sELECT t.xidusn, t.xidslot, t.xidsqn, t.start_time, t.start_scn
FROM v$transaction t JOIN v$session s ON t.addr = s.taddr
WHERE s.sid = 391;
XIDUSN XIDSLOT XIDSQN START_TIME START_SCN
---------- ---------- ---------- ---------------------------------------- ----------
3005 12 6160 08/09/24 17:03:57 205813214
SQL> @trans
SID SERIAL# USERNAME TADDR SES_ADDR USED_UBLK USED_UREC 0xFLAG STATUS START_DATE XIDUSN XIDSLOT XIDSQN XID PRV_XID PTX_XID
---------- ---------- ------------------------- ---------------- ---------------- ---------- ---------- ------------------ ---------------------------------------------------------- ------------------- ---------- ---------- ---------- ---------------- ---------------- ----------------
391 30207 ANBOB 000000014F24D718 000000015C44C080 1 3 1E03 ACTIVE 2024-08-09 17:03:57 3005 12 6160 BD0B0C0010180000 0000000000000000 0000000000000000
Note:
如果是历史的可以从ASH , DASH取相关信息, 还有oracle是支持logminer分析redo， 前几天看到一个国产友商一线交付吐槽oracle logminer不支持redo log, 呵，上个世纪就支持了。
查找所在的日志文件
SQL> SELECT name
FROM v$archived_log
WHERE 205813214 BETWEEN first_change# AND next_change# - 1; 2 3
no rows selected
SQL> select group#,thread#,sequence# from v$log where 205813214 BETWEEN first_change# AND next_change# - 1;
GROUP# THREAD# SEQUENCE#
---------- ---------- ----------
6 1 945
12 2 955
SQL> alter system switch logfile;
System altered.
SQL> SELECT name
FROM v$archived_log
WHERE 205813214 BETWEEN first_change# AND next_change# - 1; 2 3
NAME
----------------------------------------------------------------------------------------------------------
+FRA/rac11g/archivelog/2024_08_09/thread_2_seq_955.1621.1176570513
SQL> @log
Show redo log layout from V$LOG, V$STANDBY_LOG and V$LOGFILE...
GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARCHIV STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME
---------- ---------- ---------- ---------- ---------- ---------- ------ ----------- ------------- ------------------- ------------ -------------------
1 2 952 1073741824 512 1 YES INACTIVE 187215083 2024-07-31 16:38:37 187215085 2024-07-31 16:38:37
2 2 953 1073741824 512 1 YES INACTIVE 187215164 2024-07-31 16:38:54 192871775 2024-08-03 10:07:30
5 1 944 1073741824 512 1 YES INACTIVE 194586108 2024-08-04 06:00:36 202118806 2024-08-07 22:00:19
6 1 945 1073741824 512 1 NO CURRENT 202118806 2024-08-07 22:00:19 2.8147E+14
7 1 940 1073741824 512 1 YES INACTIVE 182546207 2024-07-29 11:05:09 182546211 2024-07-29 11:05:09
8 1 941 1073741824 512 1 YES INACTIVE 182546211 2024-07-29 11:05:09 185613572 2024-07-30 22:01:00
9 1 942 1073741824 512 1 YES INACTIVE 185613572 2024-07-30 22:01:00 187215140 2024-07-31 16:38:37
10 1 943 1073741824 512 1 YES INACTIVE 187215140 2024-07-31 16:38:37 194586108 2024-08-04 06:00:36
11 2 954 1073741824 512 1 YES INACTIVE 192871775 2024-08-03 10:07:30 197569215 2024-08-05 17:00:12
12 2 955 1073741824 512 1 YES ACTIVE 197569215 2024-08-05 17:00:12 205820156 2024-08-09 17:08:32
13 2 956 1073741824 512 1 NO CURRENT 205820156 2024-08-09 17:08:32 2.8147E+14
14 2 951 1073741824 512 1 YES INACTIVE 185613749 2024-07-30 22:01:01 187215083 2024-07-31 16:38:37
12 rows selected.
GROUP# STATUS TYPE IS_REC MEMBER
---------- ----------- -------------- ------ ----------------------------------------------------------------------------------------------------
1 ONLINE NO +DATA/rac11g/onlinelog/group_1.262.1164470465
2 ONLINE NO +DATA/rac11g/onlinelog/group_2.261.1164470467
5 ONLINE NO +DATA/rac11g/onlinelog/group_5.268.1164470457
6 ONLINE NO +DATA/rac11g/onlinelog/group_6.269.1164470457
7 ONLINE NO +DATA/rac11g/onlinelog/group_7.270.1164470459
8 ONLINE NO +DATA/rac11g/onlinelog/group_8.271.1164470459
9 ONLINE NO +DATA/rac11g/onlinelog/group_9.272.1164470461
10 ONLINE NO +DATA/rac11g/onlinelog/group_10.273.1164470461
11 ONLINE NO +DATA/rac11g/onlinelog/group_11.274.1164470467
12 ONLINE NO +DATA/rac11g/onlinelog/group_12.275.1164470469
13 ONLINE NO +DATA/rac11g/onlinelog/group_13.276.1164470469
14 ONLINE NO +DATA/rac11g/onlinelog/group_14.277.1164470471
Logminer分析日志
SQL> EXECUTE dbms_logmnr.add_logfile(logfilename=>'+DATA/rac11g/onlinelog/group_6.269.1164470457'); PL/SQL procedure successfully completed. SQL> EXECUTE dbms_logmnr.add_logfile(logfilename=>'+DATA/rac11g/onlinelog/group_12.275.1164470469'); PL/SQL procedure successfully completed. SQL> EXECUTE dbms_logmnr.start_logmnr(options=>dbms_logmnr.dict_from_online_catalog); PL/SQL procedure successfully completed. SQL> create table tlog as SELECT * FROM v$logmnr_contents WHERE xidusn = 3005 AND xidslt = 12 AND xidsqn = 6160;
查看logmner相关信息
SQL> @printtab "select * from tlog" SCN : 205813214 START_SCN : COMMIT_SCN : TIMESTAMP : 09-aug-2024 17:03:58 START_TIMESTAMP : COMMIT_TIMESTAMP : XIDUSN : 3005 XIDSLT : 12 XIDSQN : 6160 XID : BD0B0C0010180000 PXIDUSN : 3005 PXIDSLT : 12 PXIDSQN : 6160 PXID : BD0B0C0010180000 TX_NAME : OPERATION : START OPERATION_CODE : 6 ROLLBACK : 0 SEG_OWNER : SEG_NAME : TABLE_NAME : SEG_TYPE : 0 SEG_TYPE_NAME : TABLE_SPACE : ROW_ID : AAAa33AAAAAAAAAAAA USERNAME : ANBOB OS_USERNAME : oracle MACHINE_NAME : 11g-node2 AUDIT_SESSIONID : 3874309 SESSION# : 391 SERIAL# : 30207 SESSION_INFO : login_username=ANBOB client_info=OS_username=oracle Machine_name=11g-node2 OS_terminal=pts/1 OS_process_id=24634OS_program_name=sqlplus@11g-node2 (TNS V1-V3) THREAD# : 2 SEQUENCE# : 1 RBASQN : 955 RBABLK : 1735072 RBABYTE : 16 UBAFIL : 5 UBABLK : 0 UBAREC : 0 UBASQN : 0 ABS_FILE# : 0 REL_FILE# : 0 DATA_BLK# : 0 DATA_OBJ# : 0 DATA_OBJV# : 0 DATA_OBJD# : 0 SQL_REDO : set transaction read write; SQL_UNDO : RS_ID : 0x0003bb.001a79a0.0010 SSN : 0 CSF : 0 INFO : STATUS : 0 REDO_VALUE : 18171574 UNDO_VALUE : 18171575 SAFE_RESUME_SCN : CSCN : OBJECT_ID : EDITION_NAME : CLIENT_ID : ----------------- SCN : 205813214 START_SCN : COMMIT_SCN : TIMESTAMP : 09-aug-2024 17:03:58 START_TIMESTAMP : COMMIT_TIMESTAMP : XIDUSN : 3005 XIDSLT : 12 XIDSQN : 6160 XID : BD0B0C0010180000 PXIDUSN : 3005 PXIDSLT : 12 PXIDSQN : 6160 PXID : BD0B0C0010180000 TX_NAME : OPERATION : DELETE OPERATION_CODE : 2 ROLLBACK : 0 SEG_OWNER : ANBOB SEG_NAME : TEAM TABLE_NAME : TEAM SEG_TYPE : 2 SEG_TYPE_NAME : TABLE TABLE_SPACE : USERS ROW_ID : AAAa33AAEAAEXpfAAA USERNAME : ANBOB OS_USERNAME : oracle MACHINE_NAME : 11g-node2 AUDIT_SESSIONID : 3874309 SESSION# : 391 SERIAL# : 30207 SESSION_INFO : login_username=ANBOB client_info=OS_username=oracle Machine_name=11g-node2 OS_terminal=pts/1 OS_process_id=24634OS_program_name=sqlplus@11g-node2 (TNS V1-V3) THREAD# : 2 SEQUENCE# : 1 RBASQN : 955 RBABLK : 1735072 RBABYTE : 16 UBAFIL : 5 UBABLK : 0 UBAREC : 0 UBASQN : 0 ABS_FILE# : 5 REL_FILE# : 4 DATA_BLK# : 1145439 DATA_OBJ# : 110071 DATA_OBJV# : 1 DATA_OBJD# : 110071 SQL_REDO : delete from "ANBOB"."TEAM" where "ID" = '1' and"NAME" = 'HR' and ROWID = 'AAAa33AAEAAEXpfAAA'; SQL_UNDO : insert into "ANBOB"."TEAM"("ID","NAME") values('1','HR'); RS_ID : 0x0003bb.001a79a0.0010 SSN : 0 CSF : 0 INFO : STATUS : 0 REDO_VALUE : 18171576 UNDO_VALUE : 18171577 SAFE_RESUME_SCN : CSCN : OBJECT_ID : EDITION_NAME : CLIENT_ID : ----------------- SCN : 205813214 START_SCN : COMMIT_SCN : TIMESTAMP : 09-aug-2024 17:03:58 START_TIMESTAMP : COMMIT_TIMESTAMP : XIDUSN : 3005 XIDSLT : 12 XIDSQN : 6160 XID : BD0B0C0010180000 PXIDUSN : 3005 PXIDSLT : 12 PXIDSQN : 6160 PXID : BD0B0C0010180000 TX_NAME : OPERATION : INTERNAL OPERATION_CODE : 0 ROLLBACK : 0 SEG_OWNER : SEG_NAME : TABLE_NAME : SEG_TYPE : 0 SEG_TYPE_NAME : TABLE_SPACE : ROW_ID : AAAa34AAAAAAAAAAAA USERNAME : ANBOB OS_USERNAME : oracle MACHINE_NAME : 11g-node2 AUDIT_SESSIONID : 3874309 SESSION# : 391 SERIAL# : 30207 SESSION_INFO : login_username=ANBOB client_info=OS_username=oracle Machine_name=11g-node2 OS_terminal=pts/1 OS_process_id=24634OS_program_name=sqlplus@11g-node2 (TNS V1-V3) THREAD# : 2 SEQUENCE# : 1 RBASQN : 955 RBABLK : 1735073 RBABYTE : 104 UBAFIL : 5 UBABLK : 21006622 UBAREC : 21 UBASQN : 1582 ABS_FILE# : 4 REL_FILE# : 0 DATA_BLK# : 0 DATA_OBJ# : 110072 DATA_OBJV# : 0 DATA_OBJD# : 110072 SQL_REDO : SQL_UNDO : RS_ID : 0x0003bb.001a79a1.0068 SSN : 0 CSF : 0 INFO : STATUS : 0 REDO_VALUE : 18171578 UNDO_VALUE : 18171579 SAFE_RESUME_SCN : CSCN : OBJECT_ID : EDITION_NAME : CLIENT_ID : ----------------- SCN : 205813214 START_SCN : COMMIT_SCN : TIMESTAMP : 09-aug-2024 17:03:58 START_TIMESTAMP : COMMIT_TIMESTAMP : XIDUSN : 3005 XIDSLT : 12 XIDSQN : 6160 XID : BD0B0C0010180000 PXIDUSN : 3005 PXIDSLT : 12 PXIDSQN : 6160 PXID : BD0B0C0010180000 TX_NAME : OPERATION : DELETE OPERATION_CODE : 2 ROLLBACK : 0 SEG_OWNER : ANBOB SEG_NAME : MEMB TABLE_NAME : MEMB SEG_TYPE : 2 SEG_TYPE_NAME : TABLE TABLE_SPACE : USERS ROW_ID : AAAa35AAEAAEXpvAAB USERNAME : ANBOB OS_USERNAME : oracle MACHINE_NAME : 11g-node2 AUDIT_SESSIONID : 3874309 SESSION# : 391 SERIAL# : 30207 SESSION_INFO : login_username=ANBOB client_info=OS_username=oracle Machine_name=11g-node2 OS_terminal=pts/1 OS_process_id=24634OS_program_name=sqlplus@11g-node2 (TNS V1-V3) THREAD# : 2 SEQUENCE# : 1 RBASQN : 955 RBABLK : 1735073 RBABYTE : 316 UBAFIL : 5 UBABLK : 0 UBAREC : 0 UBASQN : 0 ABS_FILE# : 5 REL_FILE# : 4 DATA_BLK# : 1145455 DATA_OBJ# : 110073 DATA_OBJV# : 2 DATA_OBJD# : 110073 SQL_REDO : delete from "ANBOB"."MEMB" where "ID" = '2' and"NAME" = 'adm' and "TID" = '1' and "TYPE_ID" IS NULL and ROWID ='AAAa35AAEAAEXpvAAB'; SQL_UNDO : insert into"ANBOB"."MEMB"("ID","NAME","TID","TYPE_ID") values ('2','adm','1',NULL); RS_ID : 0x0003bb.001a79a1.013c SSN : 0 CSF : 0 INFO : STATUS : 0 REDO_VALUE : 18171580 UNDO_VALUE : 18171581 SAFE_RESUME_SCN : CSCN : OBJECT_ID : EDITION_NAME : CLIENT_ID :
查找ENQ TM 的父表
-- 如果知道TM 的表(--子表)为MEMB, 查找当时事务在哪个父表上? SQL> select xid,timestamp,OPERATION,SESSION#,scn from tlog where TABLE_NAME='MEMB' and TIMESTAMP between to_date('2024/08/09 17:02:57','yyyy/mm/dd hh24:mi:ss') and to_date('2024/08/09 17:05:57','yyyy/mm/dd hh24:mi:ss'); 2 3 XID TIMESTAMP OPERATION SESSION# SCN ---------------- ------------------- ---------------------------------------------------------------- ---------- ---------- BD0B0C0010180000 2024-08-09 17:03:58 DELETE 391 205813214 SQL> select SCN , START_SCN ,COMMIT_SCN ,TIMESTAMP ,START_TIMESTAMP , COMMIT_TIMESTAMP, table_name ,SQL_REDO,MACHINE_NAME from tlog where (xid,timestamp,OPERATION,SESSION#,scn ) in( 2 select xid,timestamp,OPERATION,SESSION#,scn from tlog 3 where TABLE_NAME='MEMB' and TIMESTAMP 4 between to_date('2024/08/09 17:02:57','yyyy/mm/dd hh24:mi:ss') and to_date('2024/08/09 17:05:57','yyyy/mm/dd hh24:mi:ss') 5* ) SCN START_SCN COMMIT_SCN TIMESTAMP START_TIMESTAMP COMMIT_TIMESTAMP TABLE_NAME SQL_REDO MACHINE_NA ---------- ---------- ---------- ------------------- ------------------- ------------------- ---------- ------------------------------------------------------------ ---------- 205813214 2024-08-09 17:03:58 TEAM delete from "ANBOB"."TEAM" where "ID" = '1' and "NAME" = 'HR 11g-node2 ' and ROWID = 'AAAa33AAEAAEXpfAAA'; 205813214 2024-08-09 17:03:58 MEMB delete from "ANBOB"."MEMB" where "ID" = '2' and "NAME" = 'ad 11g-node2 m' and "TID" = '1' and "TYPE_ID" IS NULL and ROWID = 'AAAa35 AAEAAEXpvAAB';
Note：
影响表当前子表MEMB的同一个事务中操作的父表，就是源操作对象TEAM。
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。