Data Guard gap history

V$ARCHIVED_LOG has a lot of information, and one that is interesting in a Data Guard configuration is APPLIED, which a boolean, or rather a VARCHAR2(3) YES/NO as there are no booleans in Oracle SQL. But I would love to see a DATE or TIMESTAMP for it. As a workaround, here is a little AWK script that parses the standby alert.log to get this information. And join it with V$ARCHIVED_LOG.COMPLETION_TIME to see if we had gaps in the past between the archived logs and applied ones.

awk '
BEGIN {
print "set linesize 200 pagesize 1000"
print "column completion_time format a32"
print "column applied_time format a38"
print "column gap format a30"
s="with a as("
}
/^[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T[0-9][0-9]:[0-9][0-9]:[0-9][0-9][.][0-9]*[+][0-9]*:[0-9]*/ {
sub(/T/," ");ts=$0
}
/Media Recovery Log/{
print s" select timestamp" q ts q "applied_time,"q $NF q "name from dual "
s=" union all"
}
END{
print ") select thread#,sequence#,cast(completion_time as timestamp) completion_time,applied_time,applied_time-completion_time gap"
print " from a right outer join v$archived_log using(name) order by completion_time, applied_time;"
}
' q="'" $ORACLE_BASE/diag/rdbms/?*/?*/trace/alert_*.log | sqlplus -s / as sysdba

The result is something like this:

This tells me that I had a two hours gap around 12:15 that was resolved quickly.

Another example (RAC):

Here is an example in MAA (Data Guard + RAC) which encountered some problems. On one node I can see 3 recovery attempts for Thread 1 Sequence 8:

Actually, the recovery failed 3 times on this instance. Here is the detail in alert.log:

[oracle@cdb1-dg02-2 ~]$ grep -A 2 o1_mf_1_8_g1sqm9kw $ORACLE_BASE/diag/rdbms/?*/?*/trace/alert_*.log
PR00 (PID:30983): Media Recovery Log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2018-12-21T12:37:05.588750+00:00
Completed: ALTER DATABASE RECOVER MANAGED STANDBY DATABASE DISCONNECT NODELAY
--
Media Recovery Log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T09:37:13.802072+00:00
Starting background process NSV0
--
Errors with log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T09:38:12.389363+00:00
Media Recovery user canceled with status 16016
--
Media Recovery Log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T09:38:39.837743+00:00
Starting background process NSV0
--
Errors with log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T09:39:37.412067+00:00
Media Recovery user canceled with status 16016
--
Media Recovery Log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T09:40:04.846300+00:00
Starting background process NSV0
--
Errors with log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T09:41:02.277054+00:00
Media Recovery user canceled with status 16016
--
Media Recovery Log /u03/app/oracle/fast_recovery_area/ORCLDG02/archivelog/2018_12_21/o1_mf_1_8_g1sqm9kw_.arc
2019-01-05T14:32:06.257452+00:00
Starting background process RSM0

Then the other node attempted the recovery and failed 4 times before it is successful:

I used this only once. Usually, the apply gap is monitored in real-time from V$DATAGUARD_STATS (APPLY_LAG from TIME_COMPUTED). If you have any better idea to verify the past gap, please add a comment here or on the Twitter thread:

Of course, the best would be an Enhancement Request to get the APPLIED_TIME in V$ARCHIVED_LOG. Anyway, if you open an Active Data Guard for reporting, it is not a bad idea to have an heartbeat table with a scheduled timestamp update so that you can include the ‘as of’ date in your report.