云贝教育 |【技术文章】file dump analysis

作者：刘晓峰

原文链接：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)