重做日志时间戳说明

首先创建一个包括序列号与时间戳的表，通过对该表插入当前时间戳并记录插入操作的开始时间，进行中时间，与结束时间，以便与重做日志中的时间戳对比。 表的定义如下：

create table tim (tn int,itime timestamp);

使用以下匿名块插入数据：

declare

stime timestamp;

dtime timestamp;

etime timestamp;

begin

for i in 1 .. 10 loop

stime := systimestamp;

insert into tim values (i, systimestamp);

etime := systimestamp;

select itime into dtime from tim where tn = i;

dbms_output.put_line('start time: ' || to_char(stime,'HH24:MI:SS:FF') || ' doing time: ' ||

to_char(dtime,'HH24:MI:SS:FF') || ' end time:' || to_char(etime,'HH24:MI:SS:FF'));

dbms_lock.sleep(2.9);

commit;

end loop;

end;

其中stime，dtime,etime,分别记录了每次插入的开始时间，进行中时间，以及结束的时间，操作结束后输出以上时间，之后休眠2.9秒，COMMIT之后继续循环。该过程输出如下：

start time: 15:10:06:986235000 doing time: 15:10:06:987493000 end time:15:10:06:987962000

start time: 15:10:09:894372000 doing time: 15:10:09:894505000 end time:15:10:09:894738000

start time: 15:10:12:796921000 doing time: 15:10:12:797057000 end time:15:10:12:797293000

start time: 15:10:15:698497000 doing time: 15:10:15:698642000 end time:15:10:15:698856000

start time: 15:10:18:601077000 doing time: 15:10:18:601222000 end time:15:10:18:601451000

start time: 15:10:21:502664000 doing time: 15:10:21:502803000 end time:15:10:21:503044000

start time: 15:10:24:405294000 doing time: 15:10:24:405435000 end time:15:10:24:405673000

start time: 15:10:27:307828000 doing time: 15:10:27:307979000 end time:15:10:27:308193000

start time: 15:10:30:209477000 doing time: 15:10:30:209619000 end time:15:10:30:209865000

start time: 15:10:33:112033000 doing time: 15:10:33:112173000 end time:15:10:33:112397000

可以看到每次循环内开始时间，进行中时间，结束时间的差值很小，证明插入是在瞬间完成的。 之后我们查看tim表中的内容：

select tn,to_char(itime,'HH24:MI:SS:FF') ITIME ,dump(itime,16) HEX_ITIME from tim;

TN	ITIME	HEX_ITIME
1	15:10:06:987493	Typ=180 Len=11: 78,6d,6,e,10,b,7,3a,db,f2,88
2	15:10:09:894505	Typ=180 Len=11: 78,6d,6,e,10,b,a,35,51,10,28
3	15:10:12:797057	Typ=180 Len=11: 78,6d,6,e,10,b,d,2f,82,1f,e8
4	15:10:15:698642	Typ=180 Len=11: 78,6d,6,e,10,b,10,29,a4,6e,50
5	15:10:18:601222	Typ=180 Len=11: 78,6d,6,e,10,b,13,23,d5,eb,70
6	15:10:21:502803	Typ=180 Len=11: 78,6d,6,e,10,b,16,1d,f8,2a,38
7	15:10:24:405435	Typ=180 Len=11: 78,6d,6,e,10,b,19,18,2a,72,78
8	15:10:27:307979	Typ=180 Len=11: 78,6d,6,e,10,b,1c,12,5b,62,f8
9	15:10:30:209619	Typ=180 Len=11: 78,6d,6,e,10,b,1f,c,7e,88,38
10	15:10:33:112173	Typ=180 Len=11: 78,6d,6,e,10,b,22,6,af,9f,c8

ITIME即插入操作中的时间，HEX_ITIME为ITIME在数据块中的16进制存放格式，用以与重做日志中的16进制数据对比。 我们dump当前的重做日志，该日志包括了方才所做的DML操作：

alter system dump logfile '/u01/oradata/orcl/redo01.log';

查看dump所产生的跟踪文件，可以发现以下记录：

REDO RECORD - Thread:1 RBA: 0x000026.0000000c.0010 LEN: 0x02a0 VLD: 0x0d SCN: 0x0000.000b727b SUBSCN:  1 06/14/2009 15:10:09 CHANGE #1 TYP:1 CLS: 1 AFN:1 DBA:0x0040ebf2 OBJ:51447 SCN:0x0000.000b7279 SEQ:  1 OP:13.5 KTSFRBFMT (block format) redo: Segobjd: 0x0000c8f7 type: 1 itls: 2 CHANGE #2 TYP:0 CLS: 1 AFN:1 DBA:0x0040ebf2 OBJ:51447 SCN:0x0000.000b727b SEQ:  1 OP:13.6 KTSFRBLNK (block link modify) redo:  Opcode: LSET (lock set) Next dba: 0x0040ebf3 itli: 0 CHANGE #3 TYP:0 CLS: 1 AFN:1 DBA:0x0040ebf2 OBJ:51447 SCN:0x0000.000b727b SEQ:  2 OP:13.6 KTSFRBLNK (block link modify) redo:  Opcode: LWRT (lock write) Next dba: 0x00000000 itli: 0 CHANGE #4 TYP:0 CLS: 4 AFN:1 DBA:0x0040ebf1 OBJ:51447 SCN:0x0000.000b726a SEQ:  1 OP:13.7 KTSFRGRP (fgb/shdr modify freelist) redo: Opcode: HWMMV (move hwm) NBK: 1 Opcode: LUPD_LLIST (link a list) Slot no: 0, Count: 1 Flag: = 1 xid or slot0 ccnt:  0x0000.000.00000001 Head:  0x0040ebf2 Tail:  0x0040ebf2 CHANGE #5 TYP:0 CLS: 1 AFN:1 DBA:0x0040ebf2 OBJ:51447 SCN:0x0000.000b727b SEQ:  3 OP:11.2 KTB Redo op: 0x01  ver: 0x01 op: F  xid:  0x0009.02b.0000015d    uba: 0x00808df4.0163.24 KDO Op code: IRP row dependencies Disabled xtype: XA flags: 0x00000000  bdba: 0x0040ebf2  hdba: 0x0040ebf1 itli: 1  ispac: 0  maxfr: 4863 tabn: 0 slot: 0(0x0) size/delt: 18 fb: --H-FL-- lb: 0x1  cc: 2 null: -- col  0: [ 2]  c1 02 col  1: [11]  78 6d 06 0e 10 0b 07 3a db f2 88

在以上重做记录(REDO RECORD)的CHANGE #5中包含了插入TIMESTAMP “col  1: [11]  78 6d 06 0e 10 0b 07 3a db f2 88”即表中第一条数据的ITIME列为15:10:06:987493，而该条重做记录的时间戳为：15:10:09，要晚于插入的进行中时间，与插入结束时间。

REDO RECORD - Thread:1 RBA: 0x000026.0000000e.0010 LEN: 0x01e4 VLD: 0x0d SCN: 0x0000.000b727d SUBSCN:  1 06/14/2009 15:10:12 CHANGE #1 TYP:2 CLS: 1 AFN:1 DBA:0x0040ebf2 OBJ:51447 SCN:0x0000.000b727b SEQ:  5 OP:11.2 KTB Redo op: 0x01  ver: 0x01 op: F  xid:  0x0003.026.00000141    uba: 0x00806194.0257.19 KDO Op code: IRP row dependencies Disabled xtype: XA flags: 0x00000000  bdba: 0x0040ebf2  hdba: 0x0040ebf1 itli: 2  ispac: 0  maxfr: 4863 tabn: 0 slot: 1(0x1) size/delt: 18 fb: --H-FL-- lb: 0x2  cc: 2 null: -- col  0: [ 2]  c1 03 col  1: [11]  78 6d 06 0e 10 0b 0a 35 51 10 28

以上为后一条重做记录,该记录的CHANGE #1中包含了插入TIMESTAMP” col  1: [11]  78 6d 06 0e 10 0b 0a 35 51 10 28”即ITIME列为15:10:09:894505，而该条重做记录的时间戳为：15:10:12。 以上实验可以证明，重做日志中记录的时间戳并不是SQL语句提交的时间，也晚于SQL语句完成的时间，实际为重做记录由缓存形式写至在线日志文件的时间。即SQL语句的完成时间一般都要早于重做日志中相应记录的时间戳。由于LGWR进程至少3秒会写出一次的特性，重做日志中的时间戳最早为语句的结束时间，最晚为语句结束后的三秒。