雲貝教育 |【技術文章】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)