Why Oracle DataGuard real time apply has apply lag?

Here is the case:

On standby database:

Check the apply lag:

SQL>         select name,value from v$dataguard_stats where name in ('transport lag','apply lag') and (value > '+00 01' or value is null);

NAME                 VALUE                                                                          

-------------------- --------------------                                                          

apply lag            +00 08:19:40                                                                   

SQL> SELECT INST_ID,  DEST_ID,  DEST_NAME,  STATUS,  TYPE,  SRL,  RECOVERY_MODE FROM  gV$ARCHIVE_DEST_STATUS WHERE  DEST_ID=1;

   INST_ID    DEST_ID DEST_NAME                            STATUS    TYPE           SRL RECOVERY_MODE
---------- ---------- ------------------------------------ --------- -------------- --- -----------------------
         2          1 LOG_ARCHIVE_DEST_1                   VALID     LOCAL          NO  MANAGED REAL TIME APPLY
         3          1 LOG_ARCHIVE_DEST_1                   VALID     LOCAL          NO  MANAGED REAL TIME APPLY

         1          1 LOG_ARCHIVE_DEST_1                   VALID     LOCAL          NO  MANAGED REAL TIME APPLY

Notice that the SRL column above has value "NO", though the recovery_mode is "REAL TIME APPLY"

SQL> SELECT inst_id,PROCESS, pid,client_pid,client_process,STATUS, THREAD#, SEQUENCE#, BLOCK#, BLOCKS FROM gV$MANAGED_STANDBY where (process='RFS' and thread#<>0) or process<>'RFS'   order by process, inst_id,thread#;

   INST_ID PROCESS          PID CLIENT_PID                               CLIENT_P STATUS          THREAD#  SEQUENCE#     BLOCK#     BLOCKS
---------- --------- ---------- ---------------------------------------- -------- ------------ ---------- ---------- ---------- ----------
         1 ARCH           29823 29823                                    ARCH     CLOSING               1      26278          1         26
         1 ARCH           30054 30054                                    ARCH     CLOSING               2      26109       4096        486
         1 ARCH           30049 30049                                    ARCH     CLOSING               3      26114          1         35
         1 ARCH           30061 30061                                    ARCH     CLOSING               3      26122          1         20
         2 ARCH           27704 27704                                    ARCH     CONNECTED             0          0          0          0
         2 ARCH           27706 27706                                    ARCH     CLOSING               1      26283          1        139
         2 ARCH           27658 27658                                    ARCH     CLOSING               1      26285          1         15
         2 ARCH           27708 27708                                    ARCH     CLOSING               3      26121     157696       1059
         3 ARCH           28723 28723                                    ARCH     CLOSING               1      26277       4096       1828
         3 ARCH           28725 28725                                    ARCH     CLOSING               2      26132      92160        617
         3 ARCH           28637 28637                                    ARCH     CLOSING               2      26133          1         18

   INST_ID PROCESS          PID CLIENT_PID                               CLIENT_P STATUS          THREAD#  SEQUENCE#     BLOCK#     BLOCKS
---------- --------- ---------- ---------------------------------------- -------- ------------ ---------- ---------- ---------- ----------
         3 ARCH           28721 28721                                    ARCH     CLOSING               2      26131          1        926
         1 MRP0           31156 N/A                                      N/A      WAIT_FOR_LOG          3      26123          0          0
         1 RFS            18420 18413                                    LGWR     IDLE                  3      26123     227156          1
         2 RFS            13943 25585                                    LGWR     IDLE                  1      26286     346513          1
         3 RFS            24425 2799                                     LGWR     IDLE                  2      26134     602093          1


16 rows selected.

Notice above  that the MRP0 process status is "WAIT_FOR_LOG" on thread#=3 and sequence#=26123, which  RFS on INST_ID=1 is responsible.

SQL> select thread#,group#,status from v$standby_log;

   THREAD#     GROUP# STATUS
---------- ---------- ----------
         1         16 ACTIVE
         1         17 UNASSIGNED
         2         18 ACTIVE
         2         19 UNASSIGNED
         3         20 UNASSIGNED
         3         21 UNASSIGNED

6 rows selected.

Notice above that Thread# 3 standby log is not active.

Let's check the alert log on INST_ID 1 then.

So, the RFS could not find standby redo logfile available... that's why SRL is not being used.

What happened during that time? 

select thread#,name,sequence#,completion_time,STANDBY_DEST,archived,applied from v$archived_log where completion_time>sysdate-12/24 and name='MYSTBY' order by completion_time;

THREAD# NAME        SEQUENCE# COMPLETION_TIME   STA ARC APPLIED

------- ---------- ---------- ----------------- --- --- -------

      3 BCFPSTBY        26121 20170623 00:09:08 YES YES YES

      1 BCFPSTBY        26284 20170623 00:09:09 YES YES YES

      2 BCFPSTBY        26132 20170623 00:09:10 YES YES YES

      1 BCFPSTBY        26285 20170623 00:09:20 YES YES YES

      3 BCFPSTBY        26122 20170623 00:09:20 YES YES YES

      2 BCFPSTBY        26133 20170623 00:09:20 YES YES YES

So the standby database only has two SRL groups, but there were two redo log switch during RMAN backup, and RFS could not find available SRL to use, hence the real time apply is not functioning.

The solutions is to create more SRL groups.

STBY>
recover managed standby database cancel;
alter database add standby logfile THREAD 1 group 22 ('+oraflash01') SIZE 524288000;
alter database add standby logfile THREAD 2 group 23 ('+oraflash01') SIZE 524288000;
alter database add standby logfile THREAD 3 group 24 ('+oraflash01') SIZE 524288000;
alter database add standby logfile THREAD 1 group 25 ('+oraflash01') SIZE 524288000;
alter database add standby logfile THREAD 2 group 26 ('+oraflash01') SIZE 524288000;

alter database add standby logfile THREAD 3 group 27 ('+oraflash01') SIZE 524288000;
recover managed standby database using current logfile disconnect;

PRI> alter system archive log current;
STBY>SELECT inst_id,PROCESS, pid,client_pid,client_process,STATUS, THREAD#, SEQUENCE#, BLOCK#, BLOCKS FROM gV$MANAGED_STANDBY where (process='RFS' and thread#<>0) or process<>'RFS'   order by process, inst_id,thread#;
   INST_ID PROCESS          PID CLIENT_PID                               CLIENT_P STATUS          THREAD#  SEQUENCE#     BLOCK#     BLOCKS
---------- --------- ---------- ---------------------------------------- -------- ------------ ---------- ---------- ---------- ----------
     ...

         3 MRP0            8069 N/A                                      N/A      APPLYING_LOG          1      26287        196    1024000

Now the MRP0 status is "applying_log" as shown above.

SQL> select thread#,group#,sequence#,status,last_change#,last_time from v$standby_log;

  THREAD#     GROUP#  SEQUENCE# STATUS       LAST_CHANGE# LAST_TIME
---------- ---------- ---------- ---------- -------------- -----------------
         1         16          0 UNASSIGNED
         1         17      26287 ACTIVE      9776892257484 20170623 10:47:46
         2         18          0 UNASSIGNED
         2         19      26135 ACTIVE      9776892257486 20170623 10:47:46
         3         20      26124 ACTIVE      9776892257487 20170623 10:47:46
         3         21          0 UNASSIGNED
         1         22          0 UNASSIGNED
         2         23          0 UNASSIGNED
         3         24          0 UNASSIGNED
         1         25          0 UNASSIGNED
         2         26          0 UNASSIGNED

   THREAD#     GROUP#  SEQUENCE# STATUS       LAST_CHANGE# LAST_TIME
---------- ---------- ---------- ---------- -------------- -----------------
         3         27          0 UNASSIGNED

12 rows selected.

As shown above, all three threads has active SRL group, and last_change# and last_time is up to date.

But SRL is still showing "NO", we just stop checking on this column anymore.
SQL> SELECT INST_ID,  DEST_ID,  DEST_NAME,  STATUS,  TYPE,  SRL,  RECOVERY_MODE FROM  gV$ARCHIVE_DEST_STATUS WHERE  DEST_ID=1;

   INST_ID    DEST_ID DEST_NAME                            STATUS    TYPE           SRL RECOVERY_MODE
---------- ---------- ------------------------------------ --------- -------------- --- -----------------------
         3          1 LOG_ARCHIVE_DEST_1                   VALID     LOCAL          NO  MANAGED REAL TIME APPLY
         1          1 LOG_ARCHIVE_DEST_1                   VALID     LOCAL          NO  MANAGED REAL TIME APPLY

         2          1 LOG_ARCHIVE_DEST_1                   VALID     LOCAL          NO  MANAGED REAL TIME APPLY

Problem solved.

The following note is helpful:
https://community.oracle.com/docs/DOC-1007036