LOGMNR挖掘日志与DUMP日志对比

发布时间：2020-12-14 04:11:12 所属栏目：大数据来源：网络整理

导读：很多人都知道使用LOGMNR来分析日志,但是很少有人来使用DUMP来分析日志,具体是因为LOGMNR分析出来的信息方便查阅,也便于理解. 但是有些时候我们还是需要DUMP来分析日志文件,因为它记录的更详细,更真实。(其实一般的LOGMNR分析的日志不是很全的) ? 有次LOGMNR

很多人都知道使用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:APPADMINISTRATORORADATAORCLREDO03.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:APPADMINISTRATORORADATAORCLREDO03.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','SCOTT','DUMP_A',NULL,'NONE','TABLE','USERS',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:APPADMINISTRATORORADATAORCLREDO03.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

col?1 --第二列，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,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

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

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

（编辑：李大同）

【声明】本站内容均来自网络，其相关言论仅代表作者个人观点，不代表本站立场。若无意侵犯到您的权利，请及时与联系站长删除相关内容!