Standby Log Apply Elapsed Time

Oct 24, 2008 / By Marc Billette

Tags: ,

This has been discussed before by my colleague Paul Moen in his article on Oracle standby recovery rate monitoring, but I recently made a discovery that makes it easier to generate both statistics on log apply performance, and more useful stats too.

First, let me say that this discovery is based on my observations and has not been verified with Oracle Support nor by any insider. If you know one who can confirm this, please ask him or her.

The discovery is a hidden column in the x$kcclh table, which is the underlying table for gv$log_history (and therefore v$log_history). It’s the only column not exposed in the fixed views. Why? I don’t know but it sure would be nice to have it exposed and clearly (officially) defined. The column is x$kcclh.lhtsm. It stores the timestamp of when the log began to be applied. The same timestamp as the one printed in the alert log for the “Media Recovery Log…” message and the same timestamp as the one recorded in the v$dataguard_status.message text column.

The advantage of accessing this information from the x$kcclh table is that you get access to more historical data (the number of days will vary based on your redo log switch rate and the size of the control files and possibly on other factors).

The time difference between two consecutive logs, say 1 and 2, gives us the time spent applying the log 1. At least that’s the theory. Some factors that we can’t really take into account are the log delay set in the log_archive_dest_n parameter on the primary db (it’s an optional setting), and any unexpected events, such as an MRP0 process getting hung or a FAL server having trouble to send a log, etc.

Nevertheless, I feel it is very useful information. Any anomaly can be easily identified as it would come up with an unusual elapse time.

Here’s the query I use to get the log apply elapse time:

set linesize 80
select b.lhseq sequence#, b.lhtsm fromtime, a.lhtsm totime,
 ((to_date(a.lhtsm,'MM/DD/RR HH24:MI:SS') - 
   to_date(b.lhtsm,'MM/DD/RR HH24:MI:SS')) * 1440) minutes_to_apply
  from sys.x$kcclh a, sys.x$kcclh b
 where a.lhrid = b.lhrid + 1
 order by a.lhrid
;

Sample output:

SEQUENCE# FROMTIME            TOTIME              MINUTES_TO_APPLY
--------- ------------------- ------------------- ----------------
    97077 09/18/2008 03:28:32 09/18/2008 03:43:31       14.9833333
    97078 09/18/2008 03:43:31 09/18/2008 03:58:31               15
    97079 09/18/2008 03:58:31 09/18/2008 04:13:31               15
    97080 09/18/2008 04:13:31 09/18/2008 04:28:31               15
    97081 09/18/2008 04:28:31 09/18/2008 04:43:33       15.0333333
    97082 09/18/2008 04:43:33 09/18/2008 04:58:33               15
    97083 09/18/2008 04:58:33 09/18/2008 05:13:36            15.05
    97084 09/18/2008 05:13:36 09/18/2008 05:28:33            14.95
    97085 09/18/2008 05:28:33 09/18/2008 05:43:31       14.9666667
    97086 09/18/2008 05:43:31 09/18/2008 05:58:31               15

Here’s a query to show the min, max and average elapse time:

set linesize 140
col min_log_date newline
col max_log_date newline
col max_log_apply_duration for a30 newline
col min_log_apply_duration for a30 newline
col avg_log_apply_duration for a30 newline
select min(lhlot) min_log_date, max(lhlot) max_log_date,
       numtodsinterval(max(to_number(a_lhtsm - b_lhtsm)),'DAY') max_log_apply_duration,
       numtodsinterval(min(to_number(a_lhtsm - b_lhtsm)),'DAY') min_log_apply_duration,
       numtodsinterval(avg(to_number(a_lhtsm - b_lhtsm)),'DAY') avg_log_apply_duration
  from (
        select a.lhlot lhlot, 
               to_date(a.lhtsm,'MM/DD/RR HH24:MI:SS') a_lhtsm, 
               to_date(b.lhtsm,'MM/DD/RR HH24:MI:SS') b_lhtsm,
               a.lhrid
          from sys.x$kcclh a, sys.x$kcclh b
         where a.lhrid = b.lhrid + 1
       )
 order by lhrid;

Sample output:

MIN_LOG_DATE        
--------------------
MAX_LOG_DATE
--------------------
MAX_LOG_APPLY_DURATION
------------------------------
MIN_LOG_APPLY_DURATION
------------------------------
AVG_LOG_APPLY_DURATION
------------------------------
09/18/2008 04:28:30  
10/21/2008 15:06:56  
+000000000 04:16:55.999999999  
+000000000 00:00:05.999999999  
+000000000 00:11:47.666911225

The following query shows logs that took over 30 minutes to apply:

select a.lhseq, b.lhtsm fromtime, a.lhtsm totime,
       ((to_date(a.lhtsm,'MM/DD/RR HH24:MI:SS') -
         to_date(b.lhtsm,'MM/DD/RR HH24:MI:SS')) * 1440) minutes_to_apply
  from sys.x$kcclh a, sys.x$kcclh b
 where to_date(a.lhlot,'MM/DD/RR HH24:MI:SS') > sysdate - 60
   and a.lhrid = b.lhrid + 1
   and  ((to_date(a.lhtsm,'MM/DD/RR HH24:MI:SS') -
          to_date(b.lhtsm,'MM/DD/RR HH24:MI:SS')) * 1440) > 30
order by a.lhrid
;

Sample output:

 LHSEQ FROMTIME             TOTIME               MINUTES_TO_APPLY
------ -------------------- -------------------- ----------------
 98276 09/28/2008 08:04:41  09/28/2008 11:04:41               180
 98278 09/28/2008 11:25:24  09/28/2008 12:07:06              41.7
 98280 09/28/2008 12:15:35  09/28/2008 14:23:01        127.433333
 98294 09/28/2008 14:33:29  09/28/2008 15:13:33        40.0666667
 98297 09/28/2008 15:51:18  09/28/2008 16:31:42              40.4
 98423 09/28/2008 19:36:32  09/28/2008 20:20:56              44.4
 98533 09/28/2008 22:16:22  09/28/2008 22:54:11        37.8166667
 98662 09/29/2008 02:29:11  09/29/2008 03:37:19        68.1333333
 98663 09/29/2008 03:37:19  09/29/2008 04:13:37              36.3
 98664 09/29/2008 04:13:37  09/29/2008 04:44:14        30.6166667
 98669 09/29/2008 05:54:33  09/29/2008 07:19:25        84.8666667
100220 10/13/2008 07:50:41  10/13/2008 08:50:27        59.7666667
100422 10/15/2008 06:10:58  10/15/2008 10:27:54        256.933333
100537 10/16/2008 08:40:24  10/16/2008 10:05:32        85.1333333

I hope you find these queries useful for monitoring your standby database log apply rate and efficiency.

Enjoy!
Marc.

7 Responses to “Standby Log Apply Elapsed Time”

  • Asif Momen says:

    Hi Marc,

    Good findings!!!

    This will definitely be helpful when monitoring your standby databases. I will save these queries in my favorite one’s.

    I have recently been advocating using Analytic Functions in SQL to make life easier, so thought of re-writing your queries using AF.

    Query 1:
    ========
    select sequence#, fromtime, totime,
    ((to_date(totime,’MM/DD/RR HH24:MI:SS’)
    – to_date(fromtime,’MM/DD/RR HH24:MI:SS’)) * 1440) minutes_to_apply
    from (select lhseq sequence#, lhtsm fromtime,
    lead(lhtsm) over (order by lhseq) totime
    from sys.x$kcclh)
    order by sequence#

    Query 2:
    ========
    select min(lhlot) min_log_date, max(lhlot) max_log_date,
    numtodsinterval(max(to_number(a_lhtsm – b_lhtsm)),’DAY’) max_log_apply_duration,
    numtodsinterval(min(to_number(a_lhtsm – b_lhtsm)),’DAY’) min_log_apply_duration,
    numtodsinterval(avg(to_number(a_lhtsm – b_lhtsm)),’DAY’) avg_log_apply_duration
    from ( select lhlot lhlot,
    to_date(lhtsm,’MM/DD/RR HH24:MI:SS’) a_lhtsm,
    to_date(lag(lhtsm) over (order by lhrid),’MM/DD/RR HH24:MI:SS’) b_lhtsm,
    lhrid
    from sys.x$kcclh )
    order by lhrid;

    Query 3:
    ========
    select sequence#, fromtime, totime,
    ((to_date(totime,’MM/DD/RR HH24:MI:SS’)
    – to_date(fromtime,’MM/DD/RR HH24:MI:SS’)) * 1440) minutes_to_apply
    from (select lhseq sequence#, lhtsm totime,
    lag(lhtsm) over (order by lhseq) fromtime
    from sys.x$kcclh)
    where to_date(fromtime,’MM/DD/RR HH24:MI:SS’) > sysdate – 60
    and ((to_date(totime,’MM/DD/RR HH24:MI:SS’) –
    to_date(fromtime,’MM/DD/RR HH24:MI:SS’)) * 1440) > 30
    order by sequence#;

    Thanks again Marc for the findings.

    Regards

    Asif Momen
    http://momendba.blogspot.com

  • jason arneil says:

    Interesting stuff, and good spot!

    Output may be of less use in real time apply.

    jason.

  • […] Billette brings some interesting information about how you can monitor the amount of time it takes Oracle to apply logs. Jason Arneil has some very noteworthy work showing how performing an online rebalance of ASM can […]

  • an oracle dba says:

    agreed with Jason. ouput may less use in real time apply.

    but is it x$kcclh.lhtsm can be used to monitor primary instnace local archiver?

  • “oracle dba”, I don’t know if that column is useful on the primary db side. You’d have to do your own observations. I do see that the column is populated on the primary but it’s obviously not for standby log apply. Perhaps the column has double use, and that could explain why it is not exposed in the virtual views…

    Note that I’m not clear on what you would like to know about the archivers on the primary database.

  • pmlx01 says:

    great stuff about x$kcclh.lhtsm. This was info i needed and saved me plenty of time and work parsing alert to get the same data. excellent post.

  • Rich Bernat says:

    I too was frustrated by the lack of exposure of the apply rate to the standby.

    I wrote this script years ago using more common views and extrapolated the necessary information.

    rem Script: get_redo_apply_metrics.sql
    rem Reports standby apply rate with lag
    rem
    set lines 120 pages 60
    column SizeM format 9,999.9
    column “MB/sec” format 9,999.99

    select TIMESTAMP,
    completion_time “ArchTime”,
    SEQUENCE#,
    round((blocks*block_size)/(1024*1024),1) “SizeM”,
    round((TIMESTAMP-lag(TIMESTAMP,1,TIMESTAMP) OVER (order by TIMESTAMP))*24*60*60,1) “Diff(sec)
    “,
    round((blocks*block_size)/1024/ decode(((TIMESTAMP-lag(TIMESTAMP,1,TIMESTAMP)
    OVER (order by TIMESTAMP))*24*60*60),0,1,
    (TIMESTAMP-lag(TIMESTAMP,1,TIMESTAMP) OVER (order by TIMESTAMP))*24*60*60),1) “KB/sec”,
    round((blocks*block_size)/(1024*1024)/ decode(((TIMESTAMP-lag(TIMESTAMP,1,TIMESTAMP)
    OVER (order by TIMESTAMP))*24*60*60),0,1,
    (TIMESTAMP-lag(TIMESTAMP,1,TIMESTAMP) OVER (order by TIMESTAMP))*24*60*60),3) “MB/sec”,
    round(((lead(TIMESTAMP,1,TIMESTAMP) over (order by TIMESTAMP))-completion_time)*24*60*60,1) ”
    Lag(sec)”
    from v$archived_log a, v$dataguard_status dgs
    where a.name = replace(dgs.MESSAGE,’Media Recovery Log ‘,”)
    and dgs.FACILITY = ‘Log Apply Services’
    order by TIMESTAMP;

Leave a Reply

  • (will not be published)

XHTML: You can use these tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>