首先创建一个包括序列号与时间戳的表,通过对该表插入当前时间戳并记录插入操作的开始时间,进行中时间,与结束时间,以便与重做日志中的时间戳对比。
表的定义如下:
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;
|
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秒会写出一次的特性,重做日志中的时间戳最早为语句的结束时间,最晚为语句结束后的三秒。
Leave a Reply