Haibin's blog

find which sessions or SQLs generate excessive redo log

leave a comment »

Once a while we found excessive redo logs were generated in our production databases. In order to troubleshoot this issue, the first step is to find out sessions or sqls. Depending on whether the issue is still happening or not, we can use different methods to figure out the low-hanging fruit.

a.) if the issue is already gone, we can use logminer to find which operation caused this issue by follwing MOS 300395.1: How To Determine The Cause Of Lots Of Redo Generation Using LogMiner. However, there is not redo statistic in v$logmnr_contents, so we may have to guess which statement generates most of redo records based on execution count.

b.) if the issue is still happening, we have more diagnostic methods to find out sessions or SQLs.

To find out which sessions generate excessive redo,we can calcuate the ‘redo size’ delta from v$sesstat between two snapshots to find out the session which generates more redo, or simply use the Tanel Poder’s snapper.sql.

Sometimes we may find several sessions generate excessive redo when connection pool is used, and we want to find which sql from these sessions cause the issue. unfortunately, there is not a view which can tell us how much redo generated for a specific SQL.
As we know, when a transation changes a block in regular tablespaces, it generates redo records and undo records as well, and the undo consumption is recorded in v$transation(The USED_UBLK column of v$transaction view shows the number of undo blocks used and the USED_UREC column shows the number of undo records used by the transaction), Therefore, we can monitor undo usage to narrow down which SQLs generate excessive redo by sampling the sessions repeatedly.

Below is the code I used.

define   snapper_sleep="&1"
define   snapper_count="&2"

set termout on serveroutput on

declare
  cursor cur_trans is
    select s.sid ,s.sql_id,s.serial#,t.USED_UBLK
    from v$session s,  v$transaction t
    where s.saddr=t.ses_addr;
begin
   dbms_output.put_line('seq#    sid   serial#     sql_id  used_ublk ');
   for c in 1..&snapper_count loop
      for  trans_rec in cur_trans
      loop
          dbms_output.put_line(c ||'       '||trans_rec.sid  ||'  '|| trans_rec.serial# ||'   '|| trans_rec.sql_id ||'   '|| trans_rec.USED_UBLK);
      end loop;
      dbms_lock.sleep(&snapper_sleep);
   end loop;
end;
/

Note, one transaction may include multiple DMLs, and the number of undo blocks is calcualted from the start of this transaction, not from the start of current SQL, so USED_UBLK in this veiw may not be the number of undo blocks generated by the current DML. However, we should be able to find out which SQLs generate more undo/redo from samples.

Below is example.

SQL>  @test3 0.5 120
old  11:    for c in 1..&snapper_count loop
new  11:    for c in 1..120 loop
old  18:       dbms_lock.sleep(&snapper_sleep);
new  18:       dbms_lock.sleep(0.5);
seq#    sid   serial#     sql_id  used_ublk
43       246  55295   bqnss5311qu48   8
44       246  55295   bqnss5311qu48   11
45       246  55295   bqnss5311qu48   20
46       246  55295   bqnss5311qu48   35
47       246  55295   bqnss5311qu48   39
48       246  55295   bqnss5311qu48   40
49       246  55295   bqnss5311qu48   50
50       246  55295   bqnss5311qu48   71
51       246  55295   bqnss5311qu48   87
52       246  55295   ayqqj8sga53j7   1
55       256  11051   bqnss5311qu48   19
56       256  11051   bqnss5311qu48   42
57       256  11051   bqnss5311qu48   55
58       256  11051   bqnss5311qu48   83
59       256  11051   bqnss5311qu48   93
60       134  4155   bqnss5311qu48   35
61       134  4155   bqnss5311qu48   42
62       134  4155   bqnss5311qu48   56
62       134  4155   bqnss5311qu48   1
63       134  4155   bqnss5311qu48   82
64       202  3243   2hakxczvxbacn   2
65       202  3243   bqnss5311qu48   32
66       202  3243   bqnss5311qu48   59
67       202  3243   9jyxc671ps26n   78
68       202  3243   bqnss5311qu48   83
69       27  56385   9jyxc671ps26n   1
70       27  56385   9jyxc671ps26n   17
71       27  56385   9jyxc671ps26n   30
71       27  56385   9jyxc671ps26n   0
72       27  56385   9jyxc671ps26n   46
73       310  17635   9jyxc671ps26n   2
74       310  17635   9jyxc671ps26n   18
75       310  17635   9jyxc671ps26n   29
76       310  17635   9jyxc671ps26n   38
77       310  17635   9jyxc671ps26n   45
78       310  17635   9jyxc671ps26n   57
79       212  5157   9jyxc671ps26n   10
80       212  5157   9jyxc671ps26n   24
81       212  5157   9jyxc671ps26n   39
82       212  5157   9jyxc671ps26n   54
83       57  3099   9jyxc671ps26n   13
84       57  3099   9jyxc671ps26n   23
85       57  3099   9jyxc671ps26n   39
86       57  3099   9jyxc671ps26n   54
87       256  11051   ayqqj8sga53j7   1
88       256  11051   ayqqj8sga53j7   1
89       256  11051   ayqqj8sga53j7   1

PL/SQL procedure successfully completed.

From above samples, we can see sql_id: bqnss5311qu48 & 9jyxc671ps26n generated more undo/redo.

Written by Haibin Sun

August 14, 2013 at 4:54 PM

Leave a comment