Help! Select queries are…filling up my redo logs?!!

It is theoretically possible (although unlikely in a well managed system) to cause a large amount of transaction logging to occur if you do something as simple as update a row in one session, don’t commit, and repeatedly query that same row from another session. How is this possible?

Let’s assume we have a simple table name T, with a single column name C. We proceed to insert a single row into the table, update it, but don’t commit…

SQL> insert into t values(1);

1 row created.

SQL> select * from t;

         C
----------
         1

SQL> update t set c = 1;

1 row updated.

SQL>

…and in another session, repeatedly select our single row. Every 500 selects, we also print how much redo our session has generated…

import cx_Oracle, time, sys

conn = cx_Oracle.connect("rep/rep@tst11g")
cursor = conn.cursor()


for i in range(10000):
  cursor.execute("select * from t")
  for row in cursor:
    pass
  if i % 500 == 0:
    cursor.execute("select value from v$mystat natural join v$statname where name = 'redo size'")
    for row in cursor:
      print row[0]
      sys.stdout.flush()

…and see are generating about 64 bytes of redo each time we select our row…

C:\>redoOnSelect.py
948
32948
64948
96948
128948
160948
192948
224948
256948
288948
320948
352948
384948
416948
448948
480948
512948
544948
576948
608948

C:\>

When we dump the redo, we see that blocks are being cleaned out.

REDO RECORD - Thread:1 RBA: 0x00403f.0002a841.0060 LEN: 0x0040 VLD: 0x01
SCN: 0x0631.87f0c98e SUBSCN:  1 11/05/2011 12:51:40
CHANGE #1 TYP:0 CLS: 1 AFN:14 DBA:0x038000be OBJ:261599 SCN:0x0631.87f0c980 SEQ:  1 OP:4.1
Block cleanout record, scn:  0x0631.87f0c98e ver: 0x01 opt: 0x01, entries follow...

The odd part is that it shouldn’t even have to do that. It finds an active transaction in the block header for the row, goes to the undo record and finds it is still active. What is there to clean out?

Whatever the reason, I found I could generate 12MB of redo per minute with this test. That would total almost 20GB over the course of a day, from only selecting a single row from a table. You will also find a rapidly increasing value for the statistic “active txn count during cleanout” in the selecting session.

More to come. This is a good interview question 🙂