重做日志时间戳说明

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

表的定义如下:

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秒会写出一次的特性,重做日志中的时间戳最早为语句的结束时间,最晚为语句结束后的三秒。


Posted

in

by

Tags:

Comments

Leave a Reply

Your email address will not be published. Required fields are marked *