作者:刘晓峰
原文链接:http://www.tdpub.cn/Home/Blog/detail/id/1348.html
昨日使用日志矿工无法找到DML语句,因此dump在线重做日志进行分析
1.查询当前在线重做日志(归档日志没有区别)
为了让转储文件少一点,我们先切一遍
alter system switch logfile;
等待脏块刷到磁盘,刷完之后查询status就会看到ACTIVE变成INACTIVE(其实不等待也可以,因为commit一定会把日志写入current)
select l.sequence#, l.status,lf.member from v$log l ,v$logfile lf where l.group#=lf.group# order by l.sequence#;
SEQUENCE# STATUS MEMBER
8 INACTIVE /usr/local/oracle19c/oradata/ORCL/redo02A.log
8 INACTIVE /usr/local/oracle19c/oradata/ORCL/redo02.log
9 INACTIVE /usr/local/oracle19c/oradata/ORCL/redo03A.log
9 INACTIVE /usr/local/oracle19c/oradata/ORCL/redo03.log
10 CURRENT /usr/local/oracle19c/oradata/ORCL/redo01A.log
10 CURRENT /usr/local/oracle19c/oradata/ORCL/redo01.log
目前正在使用redo02.log,redo02A.log是我的日志组的另一个成员,两者内容一致,只用分析其中一个就行
2.写入一行数据
select d.current_scn from v$database d--57556920
insert into cux_logminer_test(id ) values(1); --写一行数据
commit;
select d.current_scn from v$database d--57556937
我们拿到我们操作的起止SCN对应的时间
select to_char(scn_to_timestamp(57556920),'YYYY-MM-DD HH24:MI:SS') from dual;--2023-03-08 15:11:37
select to_char(scn_to_timestamp(57556937),'YYYY-MM-DD HH24:MI:SS') from dual;--2023-03-08 15:11:43
3.dump文件
ALTER SYSTEM DUMP LOGFILE '/usr/local/oracle19c/oradata/ORCL/redo01.log' SCN MIN 57556920 SCN MAX 57556937
4.查询dump文件
select p.tracefile,p.pid from v$process p,v$session s where p.addr=s.paddr and s.sid=userenv('sid');
结果为:
/usr/local/oracle19c/diag/rdbms/orcl/ORCL/trace/ORCL_ora_3942.trc
如果找不到此文件,请切换SYS用户执行
5.分析
查询obj
select D.DATA_OBJECT_ID from dba_objects d where d.object_name='CUX_LOGMINER_TEST';--139617
然后在文件中搜索
拿到了下面的文件
(有一点疑问,这个时间戳对不上,我的修改发生在15:11:37-15:11:43之间)
REDO RECORD - Thread:1 RBA: 0x00000a.00000d82.0010 LEN: 0x020c VLD: 0x05 CON_UID: 0
SCN: 0x00000000036e3fc0 SUBSCN: 1 03/08/2023 15:11:43
(LWN RBA: 0x00000a.00000d82.0010 LEN: 0x00000002 NST: 0x0001 SCN: 0x00000000036e3fc0)
CHANGE #1 CON_ID:0 TYP:0 CLS:29 AFN:4 DBA:0x010000e0 OBJ:4294967295 SCN:0x00000000036e3f54 SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
ktudh redo: slt: 0x0003 sqn: 0x00009006 flg: 0x0012 siz: 136 fbi: 0
uba: 0x01000701.2827.1c pxid: 0x0000.000.00000000
2023-03-08 15:12:57.416 : nsmore2recv:testing for MOREDATA from transport
2023-03-08 15:12:57.416 : sntpoltsts:exit
2023-03-08 15:12:57.416 : nioqts:exit
CHANGE #2 CON_ID:0 TYP:0 CLS:30 AFN:4 DBA:0x01000701 OBJ:4294967295 SCN:0x00000000036e3f53 SEQ:1 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 136 spc: 2604 flg: 0x0012 seq: 0x2827 rec: 0x1c
xid: 0x0007.003.00009006
ktubl redo: slt: 3 wrp: 1 flg: 0x0c08 prev dba: 0x00000000 rci: 0 opc: 11.1 [objn: 139617 objd: 139617 tsn: 6]
[Undo type ] Regular undo [User undo done ] No [Last buffer split] No
[Temp object] No [Tablespace Undo ] No [User only ] No
Begin trans
prev ctl uba: 0x01000701.2827.1b prev ctl max cmt scn: 0x00000000036e35ea
prev tx cmt scn: 0x00000000036e3685
txn start scn: 0xffffffffffffffff logon user: 107
prev brb: 0x010000fd prev bcl: 0x00000000
BuExt idx: 0 flg2: 0
KDO undo record:
KTB Redo
op: 0x03 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: Z
KDO Op code: DRP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x014561cd hdba: 0x014561ca
itli: 1 ispac: 0 maxfr: 4858
tabn: 0 slot: 0(0x0)
2023-03-08 15:12:57.416 : nioqts:exit
CHANGE #3 CON_ID:0 TYP:0 CLS:1 AFN:5 DBA:0x014561cd OBJ:139617 SCN:0x0000000003693571 SEQ:1 OP:11.2 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x01 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: F xid: 0x0007.003.00009006 uba: 0x01000701.2827.1c
KDO Op code: IRP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x014561cd hdba: 0x014561ca
itli: 1 ispac: 0 maxfr: 4858
tabn: 0 slot: 0(0x0) size/delt: 6
fb: --H-FL-- lb: 0x1 cc: 1
null: -
col 0: [ 2] c1 02
2023-03-08 15:12:57.417 : nioqts:exit
CHANGE #4 MEDIA RECOVERY MARKER CON_ID:0 SCN:0x0000000000000000 SEQ:0 OP:5.20 ENC:0 FLG:0x0000
session number = 7
serial number = 12649
transaction name =
version 318767104
audit sessionid 92456934
Client Id =
login username = APPS
我们先看这一行(可以使用命令快速查找 grep '139617' /usr/local/oracle19c/diag/rdbms/orcl/ORCL/trace/ORCL_ora_11777.trc -A 20)
CHANGE #3 CON_ID:0 TYP:0 CLS:1 AFN:5 DBA:0x014561cd OBJ:139617 SCN:0x0000000003693571 SEQ:1 OP:11.2 ENC:0 RBL:0 FLG:0x0000
看到change3#就知道找到我们想要的了,详细分析先放在一边,我们赶紧使用logmine分析一下在线重做日志
BEGIN
dbms_logmnr.add_logfile(logfilename => '/usr/local/oracle19c/oradata/ORCL/redo01.log'
,options => dbms_logmnr.new);
END;
BEGIN
dbms_logmnr.start_logmnr(dictfilename => '/usr/local/oracle19c/oradata/ORCL/dictionary/dictionary.ora'
);
END;
select *from v$logmnr_contents l where l.table_name='CUX_LOGMINER_TEST';
仍然是一行都没有
现在继续我们的分析
CHANGE #3--表示对数据块的修改
TYP:0--表示正常的改变向量
AFN:5 --相对文件地址
DBA:0x014561cd--绝对文件地址
OBJ:139617--DATA OBJECT ID 也有可能是OBJECT_ID,未测试聚簇
SCN:0x0000000003693571--16进制时间戳,转成10进制57226609,转成时间2023-03-07 18:07:45 有点不理解
OP:11.2--11是行操作,
col 0: [ 2] c1 02#--0表示第一列,[2]表示2个字节,c102=select dump(1,16) from dual; 或者rawtohex(1)