Wednesday, October 05, 2005

Recording the commit time on a record

It is often useful to record the time at which a record was inserted or updated, usually achieved by an appropriate column with a SYSDATE default or using triggers. However what is harder to achieve is the time that the record was committed. But rephrasing the question to "the time the record became visible to the rest of the database/application" a solution is suggested, using a background job to identify and update records which suddenly become 'visible'.

Here I create a test table with the normal 'created_on' column set as sysdate. I have another column set as the 'create_commit_on'. This will be left null by the insert, and a batch process will run in the background to pick up the null entries and set the column to sysdate. Actually, using DBMS_JOB the job won't pick up the exact commit time, but will normally be close enough.

An index is put on the create_commit_on column, using a decode so that ONLY the null values appear in the index. This will allow those records requiring update to be identified quickly (ie without a full scan of the table). [Not that full scans are evil, but if a large proportion of the table would require this update at one time, this probably isn't a practical technique for you unless it is a very small table.]


To demonstrate, we create the table and a procedure to insert into it with a pause of a few minutes between insert and commit. We'll run this a few times.
Another procedure is created to set the commit time, and is run as a background job repeating every minute. For this you will need job processing enabled, and the demo procedures also require access to DBMS_LOCK.
drop table test;

create table test
(id number, col_a varchar2(100),
created_on date, create_commit_on date);

create index pend_ix on test (decode(create_commit_on,null,1,null));

drop sequence test_seq;

create sequence test_seq;

drop procedure set_commit_time;

create procedure set_commit_time is
begin
update test set create_commit_on=sysdate
where decode(create_commit_on,null,1,null) = 1;
end;
.
/

drop procedure add_test;

create procedure add_test is
v_pause number;
begin
v_pause := round(dbms_random.value(120,300));
insert into test
(id, col_a, created_on)
values (test_seq.nextval, 'Waiting '||round(v_pause/60,1)||' minutes', sysdate);
dbms_lock.sleep(v_pause);
end;
.
/

set serveroutput on size 100000

declare
v_num number;
begin
dbms_job.submit(v_num, 'begin set_commit_time; commit; end;',
sysdate, 'sysdate + (1/3600)');
commit;
for i in 1..10 loop
dbms_job.submit(v_num, 'declare n number; begin add_test; commit; end;');
dbms_lock.sleep(10);
commit;
end loop;
commit;
dbms_output.put_line(v_num);
end;
.
/

column col_a format a30
alter session set nls_date_format ='DD/Mon/YY HH24:MI:SS';
Select * from test order by 1;

ID COL_A CREATED_ON CREATE_COMMIT_ON
---------- ------------------------------ ------------------ ------------------
1 Waiting 3.2 minutes 05/Oct/05 11:50:58 05/Oct/05 11:54:11
2 Waiting 2.3 minutes 05/Oct/05 11:51:08 05/Oct/05 11:54:11
3 Waiting 4.6 minutes 05/Oct/05 11:51:18 05/Oct/05 11:56:22
4 Waiting 3.4 minutes 05/Oct/05 11:51:29 05/Oct/05 11:55:05
5 Waiting 3 minutes 05/Oct/05 11:51:39 05/Oct/05 11:55:05
6 Waiting 3.6 minutes 05/Oct/05 11:51:50 05/Oct/05 11:55:56
7 Waiting 4 minutes 05/Oct/05 11:52:00 05/Oct/05 11:56:22
8 Waiting 2.6 minutes 05/Oct/05 11:52:10 05/Oct/05 11:55:05
9 Waiting 4.4 minutes 05/Oct/05 11:52:21 05/Oct/05 11:57:14
10 Waiting 2.5 minutes 05/Oct/05 11:53:26 05/Oct/05 11:56:22

In my example (the random waits mean yours would be slightly different) we can see that item 3 was created prior to item 4 but waited a minute less to commit and so was actually committed earlier. Similar with items 8 and 9/10.

The same technique could be applied to updates, as long as the updates all set the COMMIT_TIME column to null (possibly through a trigger).

Normally, it is difficult to pick records added or updated in a table since a particular time, as the delay between change and commit means that changes do not necessarily become visible in the order they are inserted. Even allowing, for example, a five minute window may miss long running transactions and requires processing to cater for duplicates.

By using this technique, we can use the time the record became visible. This is not a universal solution. The update would be onerous if a large number of rows had been changed and applying this technique to lots of tables would also have an impact and risk of deadlock unless each update is committed separately.

4 comments:

andrew said...

Very useful idea!

Martin said...

Hello,
.
your approach is a good idea.
.
In 9i, using dbms_alert might allow for still more accurate commit_timestamps.
.
However in 10g the
* ORA_ROWSCN-function
seems to provide similar functionality out-of-the-box.
Checkout
* SCN_TO_TIMESTAMP(ORA_ROWSCN)
* CREATE TABLE .. ROWDEPENDENCIES
as well.
.
Thank you for sharing your solution,
Martin

Gary Myers said...

I'll have a look at the DBMS_ALERT. I was planning a followup demonstrating, rather than having the DBMS_JOB continually running in the background, it would be submitted by an AFTER INSER/UPDATE trigger, which would be more suitable for less active tables. I'll have to look at how DBMS_ALERT fits in with both.

On the SCN, while it does stand for System Commit Number (or System Change Number) and is incremented upon commit, I think the SCN value held against the INSERTed record is the one that was current for the database when the INSERT is done[1], not the one that is 'awarded' when the transaction commits. When the inserted record is written, Oracle doesn't know when the commit will happen and can't know the SCN that that commit will be awarded. And when the commit happens it doesn't go back an rewrite all those blocks with the updated SCN.
See Zhur's comment
http://asktom.oracle.com/pls/ask/f?p=4950:8:5511629952260217445::NO::F4950_P8_DISPLAYID,F4950_P8_CRITERIA:22948373947565

[1] I'm not sure exactly 'when' this 'when' is.
In this case, with rowdependencies and a direct path insert, it appears to be the time the INSERT statment started.
http://asktom.oracle.com/pls/ask/f?p=4950:8:5511629952260217445::NO::F4950_P8_DISPLAYID,F4950_P8_CRITERIA:44798632736844

But back on
http://asktom.oracle.com/pls/ask/f?p=4950:8:5511629952260217445::NO::F4950_P8_DISPLAYID,F4950_P8_CRITERIA:22948373947565
Andrew Mannering indicates the SCN isn't available directly after the update process. Maybe when it is written to the logfile ?

Material for a future blog...

Martin said...

See another idea on this at http://www.niall.litchfield.dial.pipex.com/2005/10/reinventing-wheel.html
.
BR,
Martin