LOGMNR挖掘日志与DUMP日志对比

很多人都知道使用LOGMNR来分析日志,但是很少有人来使用DUMP来分析日志,具体是因为LOGMNR分析出来的信息方便查阅,也便于理解.

但是有些时候我们还是需要DUMP来分析日志文件,因为它记录的更详细,更真实。(其实一般的LOGMNR分析的日志不是很全的)

有次LOGMNR日志分析后,我发现挖掘的信息十分诡异,我是根据ROWID查询LOGMNR分析出来的记录的,发现某个ROWID有INSERT、DELETE,却没有UPDATE操作,

而实际上根据业务分析确实是有UPDATE操作的(注意这里我也想过会有ROWID改变的情况,譬如发生行迁移等,但根据SCN及ROWID的检测发现ROWID根本没有改变),于是我开始怀疑LOGMNR分析日志的正确性，我开始了一个小测验来验证我的想法,测验如下:

首先查到现在使用的日志文件

select a.status,b.member from v$log a,v$logfile b where a.group#=b.group#;

得到当前活动(CURRENT)的日志文件为:G:\APP\ADMINISTRATOR\ORADATA\ORCL\REDO03.LOG

--创建测试表

00:41:20 scott@orcl> create table dump_a(id number,tt varchar2(20));

表已创建。

已用时间:  00: 00: 00.40

--当前的SCN号

00:41:22 scott@orcl> select dbms_flashback.get_system_change_number() a from dual;


              A
-------------
 1257368

已选择 1 行。

--插入一条数据

00:42:47 scott@orcl> insert into dump_a values(1,'w');

已创建 1 行。

已用时间:  00: 00: 00.11

--更新一条数据
00:43:44 scott@orcl> update dump_a set id=2 where id=1;

已更新 1 行。

已用时间:  00: 00: 00.14

--现在的SCN号

00:43:52 scott@orcl> select dbms_flashback.get_system_change_number() a from dual;


              A
-------------
 1267898

已选择 1 行。

--以上记SCN号是为了DUMP日志用的

/*********************使用LOGMNR 分析日志****************************/

begin dbms_logmnr.add_logfile('G:\APP\ADMINISTRATOR\ORADATA\ORCL\REDO03.LOG',dbms_logmnr.new); end;

/
begin dbms_logmnr.start_logmnr(options=>dbms_logmnr.dict_from_online_catalog); end;

/

--查询日志信息
select timestamp,scn,sql_redo
from v$logmnr_contents
where lower(sql_redo) like '%dump_a%' order by scn;

--查询结果如下:

TIMESTAMP SCN SQL_REDO
2013-4-26 23:30:14 1260172 insert into "SYS"."WRH$_SEG_STAT_OBJ"("SNAP_ID","DBID","TS#","OBJ#","DATAOBJ#","OWNER","OBJECT_NAME","SUBOBJECT_NAME","PARTITION_TYPE","OBJECT_TYPE","TABLESPACE_NAME","INDEX_TYPE","BASE_OBJ#","BASE_OBJECT_NAME","BASE_OBJECT_OWNER") values ('54','1341399145','4','70974','70974','SCOTT','DUMP_A',NULL,'NONE','TABLE','USERS',NULL,NULL,NULL,NULL);

只有这么一条记录吗？是的,确实在LOGMNR之后只有这么一条记录,即INSERT、UPDATE的操作都没有记录到.

忘记说了我的测试库是没有开归档的。开归档后redo日志写的多一点,可能LOGMNR得到的信息会多一些.

现在我们来分析这个INSERT、UPDATE到底有没有记录到REDO呢？我们来使用DUMP看看

--先停止LOGMNR的日志分析

BEGIN dbms_logmnr.end_logmnr();  END;

/

--查询表的object_Id(后面分析日志时会用到)

00:45:52 sys@orclselect object_id a from dba_objects where object_name='DUMP_A';


              A
-------------
     70974

已选择 1 行。



--利用之前的SCN, 进行指定范围日志文件的DUMP操作

00:54:18 SYS@orcl> alter system dump logfile 'G:\APP\ADMINISTRATOR\ORADATA\ORCL\REDO03.LOG' scn min  1257368 scn max 1267898;

系统已更改。

已用时间:  00: 00: 00.10

进入trace目录,找到最近的trc文件(我这里是orcl_ora_172.trc)

打开之后,直接搜索上面查询到的object_id

部分内容如下:

CHANGE #1 TYP:0 CLS: 4 AFN:4 DBA:0x0100018b OBJ:70974 SCN:0x0000.00132a36 SEQ: 1 OP:13.28
High HWM
Highwater:: 0x01000191 ext#: 0 blk#: 8 ext size: 8
#blocks in seg. hdr's freelists: 0
#blocks below: 5
mapblk 0x00000000 offset: 0
lfdba: 0x01000189 CHANGE #2 TYP:0 CLS: 8 AFN:4 DBA:0x01000189 OBJ:70974 SCN:0x0000.00132a36 SEQ: 1 OP:13.22
Redo on Level1 Bitmap Block
Redo to set hwm
Opcode: 32 Highwater:: 0x01000191 ext#: 0 blk#: 8 ext size: 8
#blocks in seg. hdr's freelists: 0
#blocks below: 5
mapblk 0x00000000 offset: 0
CHANGE #3 TYP:1 CLS: 1 AFN:4 DBA:0x0100018c OBJ:70974 SCN:0x0000.00133d95 SEQ: 1 OP:13.21
ktspbfredo - Format Pagetable Datablock
Parent(l1) DBA: 0x01000189 typ: 1 objd: 70974 itls: 2 fmt_flag: 0 poff: 0
CHANGE #4 TYP:1 CLS: 1 AFN:4 DBA:0x0100018d OBJ:70974 SCN:0x0000.00133d95 SEQ: 1 OP:13.21
ktspbfredo - Format Pagetable Datablock
Parent(l1) DBA: 0x01000189 typ: 1 objd: 70974 itls: 2 fmt_flag: 0 poff: 0
CHANGE #5 TYP:1 CLS: 1 AFN:4 DBA:0x0100018e OBJ:70974 SCN:0x0000.00133d95 SEQ: 1 OP:13.21
ktspbfredo - Format Pagetable Datablock
Parent(l1) DBA: 0x01000189 typ: 1 objd: 70974 itls: 2 fmt_flag: 0 poff: 0
CHANGE #6 TYP:1 CLS: 1 AFN:4 DBA:0x0100018f OBJ:70974 SCN:0x0000.00133d95 SEQ: 1 OP:13.21
ktspbfredo - Format Pagetable Datablock
Parent(l1) DBA: 0x01000189 typ: 1 objd: 70974 itls: 2 fmt_flag: 0 poff: 0
CHANGE #7 TYP:1 CLS: 1 AFN:4 DBA:0x01000190 OBJ:70974 SCN:0x0000.00133d95 SEQ: 1 OP:13.21
ktspbfredo - Format Pagetable Datablock
Parent(l1) DBA: 0x01000189 typ: 1 objd: 70974 itls: 2 fmt_flag: 0 poff: 0
CHANGE #8 TYP:0 CLS: 8 AFN:4 DBA:0x01000189 OBJ:70974 SCN:0x0000.00133d9e SEQ: 1 OP:13.22
Redo on Level1 Bitmap Block
Redo for state change
Len: 5 Offset: 3 newstate: 5
CHANGE #9 TYP:0 CLS: 4 AFN:4 DBA:0x0100018b OBJ:70974 SCN:0x0000.00133d9e SEQ: 1 OP:13.28
Low HWM
Highwater:: 0x01000191 ext#: 0 blk#: 8 ext size: 8
#blocks in seg. hdr's freelists: 0
#blocks below: 5
mapblk 0x00000000 offset: 0
lfdba: 0x01000189 CHANGE #10 TYP:0 CLS: 1 AFN:4 DBA:0x01000190 OBJ:70974 SCN:0x0000.00133d9e SEQ: 1 OP:11.2
KTB Redo
op: 0x01 ver: 0x01
compat bit: 4 (post-11) padding: 0
op: F xid: 0x000a.00d.000002d4 uba: 0x00c03f3c.018b.22
KDO Op code: IRP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01000190 hdba: 0x0100018b
itli: 1 ispac: 0 maxfr: 4858
tabn: 0 slot: 0(0x0) size/delt: 8
fb: --H-FL-- lb: 0x1 cc: 2
null: --
col 0: [ 2] c1 02
col 1: [ 1] 77

可以看到创建表的区块大小、HWM等等信息,注意红色的正是插入的内容.

col 0 --第一列，2代表长度是2个字节, c1 02 --代表的是数字1

col1 --第二列，1代表长度是1个字节,77 --代表的是字符w,可以这样得到,16进制的77即是10进制的119.然后

00:54:27 SYS@orcl> select chr(119) from dual;

C
-
w

已选择 1 行。

即可得到

..在后面一点马上可以看到UPDATE的操作日志,如下:

REDO RECORD - Thread:1 RBA: 0x00001b.00009dc3.00e4 LEN: 0x01c0 VLD: 0x09
SCN: 0x0000.00134807 SUBSCN:154 04/26/2013 23:31:58
CHANGE #1 TYP:2 CLS: 1 AFN:4 DBA:0x01000190 OBJ:70974 SCN:0x0000.00133df4 SEQ: 1 OP:11.19
KTB Redo
op: 0x11 ver: 0x01
compat bit: 4 (post-11) padding: 0
op: F xid: 0x0008.01b.000002e0 uba: 0x00c06f20.01c6.0f
Block cleanout record, scn: 0x0000.00134801 ver: 0x01 opt: 0x02, entries follow...
itli: 1 flg: 2 scn: 0x0000.00133df4
Array Update of 1 rows:
tabn: 0 slot: 0(0x0) flag: 0x2c lock: 2 ckix: 0
ncol: 2 nnew: 1 size: 0
KDO Op code: 21 row dependencies Disabled
xtype: XAxtype KDO_KDOM2 flags: 0x00000080 bdba: 0x01000190 hdba: 0x0100018b
itli: 2 ispac: 0 maxfr: 4858
vect = 0
col 0: [ 2] c1 03
CHANGE #2 TYP:0 CLS:31 AFN:3 DBA:0x00c00079 OBJ:4294967295 SCN:0x0000.0013419a SEQ: 1 OP:5.2
ktudh redo: slt: 0x001b sqn: 0x000002e0 flg: 0x0012 siz: 156 fbi: 0
uba: 0x00c06f20.01c6.0f pxid: 0x0000.000.00000000
CHANGE #3 TYP:0 CLS:32 AFN:3 DBA:0x00c06f20 OBJ:4294967295 SCN:0x0000.00134199 SEQ: 1 OP:5.1
ktudb redo: siz: 156 spc: 6202 flg: 0x0012 seq: 0x01c6 rec: 0x0f
xid: 0x0008.01b.000002e0
ktubl redo: slt: 27 rci: 0 opc: 11.1 objn: 70974 objd: 70974 tsn: 4
Undo type: Regular undo Begin trans Last buffer split: No
Temp Object: No
Tablespace Undo: No
0x00000000 prev ctl uba: 0x00c06f20.01c6.0d
prev ctl max cmt scn: 0x0000.001315c1 prev tx cmt scn: 0x0000.001315ce
txn start scn: 0x0000.00133d9e logon user: 81 prev brb: 12611358 prev bcl: 0 BuExt idx: 0 flg2: 0
KDO undo record:
KTB Redo
op: 0x03 ver: 0x01
compat bit: 4 (post-11) padding: 0
op: Z
Array Update of 1 rows:
tabn: 0 slot: 0(0x0) flag: 0x2c lock: 0 ckix: 0
ncol: 2 nnew: 1 size: 0
KDO Op code: 21 row dependencies Disabled
xtype: XAxtype KDO_KDOM2 flags: 0x00000080 bdba: 0x01000190 hdba: 0x0100018b
itli: 2 ispac: 0 maxfr: 4858
vect = 0
col 0: [ 2] c1 02

注意红色的,发现由c1 03 变成 c1 02,正是更新操作,update dump_a set id=2 where id=1;

这样我们发现其实一切操作其实都已经写到日志里了,只是LOGMNR挖掘的不全而已.(没有启用附加日志)

---

DUMP后的信息确实也有点艰涩难懂,字符的对应还好查找(通过转换后,查CHR)，但是数字的就不太好查了.

我查了几个没发现转换规律,有大神知道的还望指点一二.

c1 03 对应数字2;

c1 02 对应数字1;

80 对应数字0;

3e 64 66 对应数字-1

--------------------------------

已经发现转换规则如下:

09:20:27 SYS@orcl> SELECT DUMP(2,1016) FROM DUAL;

DUMP(2,1016)
-----------------
Typ=2 Len=2: c1,3

已选择 1 行。

已用时间:  00: 00: 00.00
09:20:38 SYS@orcl> SELECT DUMP(1,1016) FROM DUAL;

DUMP(1,1016)
-----------------
Typ=2 Len=2: c1,2

已选择 1 行。

已用时间:  00: 00: 00.00
09:20:43 SYS@orcl> SELECT DUMP(0,1016) FROM DUAL;

DUMP(0,1016)
---------------
Typ=2 Len=1: 80

已选择 1 行。

已用时间:  00: 00: 00.01
09:20:47 SYS@orcl> SELECT DUMP(-1,1016) FROM DUAL;

DUMP(-1,1016)
---------------------
Typ=2 Len=3: 3e,64,66

大脑一时短路了,这么简单居然没想到。。。
--------------

日期格式的有点区别:

09:39:47 SYS@orcl> SELECT DUMP(to_date('20130423','yyyymmdd'),16) FROM DUAL;

DUMP(TO_DATE('20130423','YYYYMM
-------------------------------
Typ=13 Len=8: dd,7,4,17,0,0,0,0

但是在日志文件中却是这样存储的:

col 0: [ 7] 78 71 04 17 01 01 01

---

04 17 还是能对应到0423的

只是78 71 如何对应到2013呢？

经过尝试发现是这样转换的:

78的十进制为 120

71的十进制为 113

发现除掉开始的1,两个连起来就是2013,猜测开始的1是标志AD,BC的

10:11:42 SYS@orcl>  select to_char(sysdate,'AD YYYY-MM-DD') from dual;

TO_CHAR(SYSDATE,'
-----------------
公元 2013-04-27

已选择 1 行。

已用时间:  00: 00: 00.01
10:15:21 SYS@orcl>  select to_char(sysdate,'BC YYYY-MM-DD') from dual;

TO_CHAR(SYSDATE,'
-----------------
公元 2013-04-27

转载请注明出处,谢谢！

By Cryking