Querying the amount of redo in Oracle Database

When a database starts to churn more redo then normal, it is handy to be able to extract the amount of redo over time, to be able to plot this on a graph.Β  The below query allows you to extract this info πŸ™‚

Query for redo generation

Query to obtain the amount of redo generation over time by hour and MB:

set pages 999 lines 400
select to_char(trunc(first_time, 'HH24'), 'DD/MM/YYYY HH24:MI:SS') date_by_hour, sum(round(blocks*block_size/1024/1024)) CHURN_IN_MB
from v$archived_log
group by trunc(first_time, 'HH24')
order by 1
/

Output

This is the output you will get from the query:

SQL> set pages 999 lines 400
SQL> select to_char(trunc(first_time, 'HH24'), 'DD/MM/YYYY HH24:MI:SS') date_by_hour, sum(round(blocks*block_size/1024/1024)) CHURN_IN_MB
2 from v$archived_log
3 group by trunc(first_time, 'HH24')
4 order by 1
5 /

DATE_BY_HOUR CHURN_IN_MB
------------------- -----------
07/12/2018 10:00:00 2
07/12/2018 11:00:00 51
07/12/2018 12:00:00 3731
07/12/2018 13:00:00 10857
07/12/2018 14:00:00 12505
07/12/2018 15:00:00 17493
07/12/2018 16:00:00 187
07/12/2018 17:00:00 173
07/12/2018 18:00:00 185
07/12/2018 19:00:00 137
07/12/2018 20:00:00 159
07/12/2018 21:00:00 155
07/12/2018 22:00:00 157
07/12/2018 23:00:00 183
08/12/2018 00:00:00 154
08/12/2018 01:00:00 184
08/12/2018 02:00:00 179
08/12/2018 03:00:00 179
08/12/2018 04:00:00 172
08/12/2018 05:00:00 177
08/12/2018 06:00:00 174
08/12/2018 07:00:00 172
08/12/2018 08:00:00 177
08/12/2018 09:00:00 175
08/12/2018 10:00:00 175
08/12/2018 11:00:00 220
08/12/2018 12:00:00 221
08/12/2018 13:00:00 218
08/12/2018 14:00:00 216
08/12/2018 15:00:00 214
08/12/2018 16:00:00 212
08/12/2018 17:00:00 208
08/12/2018 18:00:00 213
08/12/2018 19:00:00 207
08/12/2018 20:00:00 205
08/12/2018 21:00:00 205
08/12/2018 22:00:00 202
08/12/2018 23:00:00 228
09/12/2018 00:00:00 202
09/12/2018 01:00:00 238
09/12/2018 02:00:00 212
09/12/2018 03:00:00 227
09/12/2018 04:00:00 213
09/12/2018 05:00:00 206
09/12/2018 06:00:00 221
09/12/2018 07:00:00 222
09/12/2018 08:00:00 216
09/12/2018 09:00:00 220
09/12/2018 10:00:00 216
09/12/2018 11:00:00 217
09/12/2018 12:00:00 162
09/12/2018 13:00:00 163
09/12/2018 14:00:00 163
09/12/2018 15:00:00 160
09/12/2018 16:00:00 158
09/12/2018 17:00:00 159
09/12/2018 18:00:00 161
09/12/2018 19:00:00 157
09/12/2018 20:00:00 157
09/12/2018 21:00:00 153
09/12/2018 22:00:00 153
09/12/2018 23:00:00 176
10/12/2018 00:00:00 150
10/12/2018 01:00:00 174
10/12/2018 02:00:00 168
10/12/2018 03:00:00 167
10/12/2018 04:00:00 169
10/12/2018 05:00:00 162
10/12/2018 06:00:00 168
10/12/2018 07:00:00 166
10/12/2018 08:00:00 160
10/12/2018 09:00:00 162
10/12/2018 10:00:00 141
10/12/2018 11:00:00 144
10/12/2018 12:00:00 142
10/12/2018 13:00:00 141
10/12/2018 14:00:00 142
10/12/2018 15:00:00 169
10/12/2018 16:00:00 146
10/12/2018 17:00:00 173
10/12/2018 18:00:00 177
10/12/2018 19:00:00 175
10/12/2018 20:00:00 7278
10/12/2018 21:00:00 12604
10/12/2018 22:00:00 18154
10/12/2018 23:00:00 6844
11/12/2018 00:00:00 1350
11/12/2018 01:00:00 505
11/12/2018 02:00:00 1183
11/12/2018 03:00:00 508
11/12/2018 04:00:00 1488
11/12/2018 05:00:00 7071
11/12/2018 06:00:00 16453
11/12/2018 07:00:00 7076
11/12/2018 08:00:00 17310
11/12/2018 09:00:00 8063
11/12/2018 10:00:00 12681
11/12/2018 11:00:00 3678
11/12/2018 14:00:00 6026
11/12/2018 15:00:00 15569
11/12/2018 16:00:00 7069
11/12/2018 17:00:00 11772
11/12/2018 18:00:00 10167
11/12/2018 19:00:00 6159
11/12/2018 20:00:00 16450
11/12/2018 21:00:00 4106
11/12/2018 22:00:00 10115
11/12/2018 23:00:00 10355
12/12/2018 00:00:00 3203
12/12/2018 01:00:00 5160
12/12/2018 02:00:00 14468
12/12/2018 03:00:00 6591
12/12/2018 04:00:00 1376
12/12/2018 05:00:00 4053
12/12/2018 06:00:00 7947
12/12/2018 07:00:00 12433
12/12/2018 08:00:00 1434
12/12/2018 09:00:00 663
12/12/2018 10:00:00 1511
12/12/2018 11:00:00 654
12/12/2018 12:00:00 5661
12/12/2018 13:00:00 9817
12/12/2018 14:00:00 10148
12/12/2018 15:00:00 372
12/12/2018 16:00:00 1074
12/12/2018 17:00:00 672
12/12/2018 18:00:00 1094
12/12/2018 19:00:00 391
12/12/2018 20:00:00 2403
12/12/2018 21:00:00 827
12/12/2018 22:00:00 1108
12/12/2018 23:00:00 15575
13/12/2018 00:00:00 17219
13/12/2018 01:00:00 8255
13/12/2018 02:00:00 877
13/12/2018 03:00:00 180
13/12/2018 04:00:00 1782
13/12/2018 05:00:00 5284
13/12/2018 06:00:00 16191
13/12/2018 07:00:00 6251
13/12/2018 08:00:00 14533
13/12/2018 09:00:00 8138
13/12/2018 10:00:00 12629
13/12/2018 11:00:00 9701
13/12/2018 12:00:00 9869
13/12/2018 13:00:00 9554
13/12/2018 14:00:00 7106
13/12/2018 15:00:00 15094
13/12/2018 16:00:00 8622
13/12/2018 17:00:00 671
13/12/2018 18:00:00 1094
13/12/2018 19:00:00 370
13/12/2018 20:00:00 2332
13/12/2018 21:00:00 421

154 rows selected.

SQL>

The above output can then be used to create a pivot chart in Excel πŸ™‚

If you found this blog post useful, please like as well as follow me through my various Social Media avenues available on the sidebar and/or subscribe to this oracle blog via WordPress/e-mail.

Thanks

Zed DBA (Zahid Anwar)

ORA-00322: log 41 of thread 2 is not current copy

On a Data Guard Physical Standby, I noticed the following in the alert log:

Fri Jan 13 08:12:39 2017 
Errors in file /u01/app/oracle/diag/rdbms/v1s/V1S1/trace/V1S1_arc1_399861.trc: 
ORA-00322: log 41 of thread 2 is not current copy 
ORA-00312: online log 41 thread 2: '+RECOC1/V1S/ONLINELOG/group_41.3099.912775569' 
ORA-00322: log 41 of thread 2 is not current copy 
ORA-00312: online log 41 thread 2: '+DATAC1/V1S/ONLINELOG/group_41.807.912775567'

If you read metalink note:
Physical standby – alert*log shows ORA-322, ORA-312 intermittently (Doc ID 1592057.1)

SYMPTOMS

alert.log shows intermittently ORA-322 and ORA-312 for SRLs (standby redo logs).

CAUSE

These errors are written due to a very small timing window, when the SRL header
is being updated to reflect new content from the primary and in the same way
the ARCH process is doing its activity and seeing a CF flag entry that reflects an earlier
state.

SOLUTION

check the alert.log for any further issues. As long as ORA-322, ORA-312 is not combined with other issues, you can ignore this error.

Related Issue:
ORA-00314: log 42 of thread 2, expected sequence# 37363 doesn’t match 37361

If you found this blog post useful, please like as well as follow me through my various Social Media avenues available on the sidebar and/or subscribe to this oracle blog via WordPress/e-mail.

Thanks

Zed DBA (Zahid Anwar)

ORA-00314: log 42 of thread 2, expected sequence# 37363 doesn’t match 37361

On a Data Guard Physical Standby, I noticed the following in the alert log:

Mon Jan 30 12:37:22 2017
Errors in file /u01/app/oracle/diag/rdbms/v1s/V1S1/trace/V1S1_arc1_105040.trc:
ORA-00314: log 42 of thread 2, expected sequence# 37363 doesn't match 37361
ORA-00312: online log 42 thread 2: '+RECOC1/V1S/ONLINELOG/group_42.15446.927996415'
ORA-00314: log 42 of thread 2, expected sequence# 37363 doesn't match 37361
ORA-00312: online log 42 thread 2: '+DATAC1/V1S/ONLINELOG/group_42.1051.927996411'

If you read metalink note:
ORA-00314: LOG 404 OF THREAD 4, EXPECTED SEQUENCE# 33808 DOESN’T MATCH 33543 (Doc ID 1077564.1)

It explains that the standby redo has a corrupt entry, due to a problem (instance crash, network problem) that happened, it was receiving sequence 33808 and was corrupted in the middle. Β So the header has info on sequence 33808 but current archive sequence # being transferred is 33543.

This was confirmed when I checked the trace file:

*** 2017-01-30 12:37:17.760
----- START Event Driven Actions Dump ----
---- END Event Driven Actions Dump ----
----- START DDE Actions Dump -----
Executing SYNC actions
----- START DDE Action: 'DB_STRUCTURE_INTEGRITY_CHECK' (Async) -----
Successfully dispatched
----- END DDE Action: 'DB_STRUCTURE_INTEGRITY_CHECK' (SUCCESS, 0 csec) -----
Executing ASYNC actions
----- END DDE Actions Dump (total 0 csec) -----
Reading mirrors of log member '+DATAC1/V1S/ONLINELOG/group_42.1051.927996411' (thread 2 seq 37363 block 1)
ksfdrfms:Mirror Read file=+DATAC1/V1S/ONLINELOG/group_42.1051.927996411 fob=0x248d0ba68 bufp=0x7f4139596000 blkno=1 nbytes=512
ksfdafReadMirror: Read success from mirror side=1 logical extent number=0 disk=DATAC1_CD_01_V1OEX2CELADM01 path=o/10.1.11.14;10.1.11.15/DATAC1_CD_01_v1oex2celadm01
Mirror I/O done from ASM disk o/10.1.11.14;10.1.11.15/DATAC1_CD_01_v1oex2celadm01
DDE: Problem Key 'ORA 312' was flood controlled (0x1) (no incident)
ORA-00312: online log 42 thread 2: '+DATAC1/V1S/ONLINELOG/group_42.1051.927996411'
Read from log mirror 'DATAC1_CD_01_V1OEX2CELADM01' (thread 2 seq 37363 block 1) found corrupt block
ksfdrnms:Mirror Read file=+DATAC1/V1S/ONLINELOG/group_42.1051.927996411 fob=0x248d0ba68 bufp=0x7f4139596000 nbytes=512

Where we can see the ‘found corrupt block’.

Luckily for me, Oracle resolved this itself by doing a RFS call for the archive redo log it required and then continued media recovery πŸ™‚ :

Mon Jan 30 12:37:23 2017
RFS[2]: Selected log 42 for thread 2 sequence 37363 dbid 284911310 branch 891349070
Mon Jan 30 12:38:09 2017
Media Recovery Waiting for thread 2 sequence 37363 (in transit)
Mon Jan 30 12:38:09 2017
Recovery of Online Redo Log: Thread 2 Group 42 Seq 37363 Reading mem 0
 Mem# 0: +DATAC1/V1S/ONLINELOG/group_42.1051.927996411
 Mem# 1: +RECOC1/V1S/ONLINELOG/group_42.15446.927996415

If you’re not so lucky you can resolve following the steps in the metalink note:
ORA-00314: LOG 404 OF THREAD 4, EXPECTED SEQUENCE# 33808 DOESN’T MATCH 33543 (Doc ID 1077564.1)

Which are:
Stopping recovery
Clear standby redo log
Restart recovery

Related Issue:
ORA-00322: log 41 of thread 2 is not current copy

If you found this blog post useful, please like as well as follow me through my various Social Media avenues available on the sidebar and/or subscribe to this oracle blog via WordPress/e-mail.

Thanks

Zed DBA (Zahid Anwar)