Re: Logical Standby Issues (cont.)

  • From: "Mark Strickland" <strickland.mark@xxxxxxxxx>
  • To: oracle-l@xxxxxxxxxxxxx
  • Date: Fri, 11 Aug 2006 10:02:53 -0700

I've spent some time this morning figuring out how to read the trace
file for the Applier process.  What appears to be the marker for a row
update is a line like this:

[ 13:00:00.001] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0077.0000484f.1d0, xid: 0x0002.00f.00019952

There are a million of those.  I updated a million rows.  So, if I
count those by hour, I get these numbers:

12:53:08-12:59:59   126,472 lines
13:00:00-13:59:59   360,417 lines
14:00:00-14:59:59   173,260 lines
15:00:00-15:59:59   129,107 lines
16:00:00-16:59:59   108,840 lines
17:00:00-17:59:59     92,069 lines
18:00:00-18:06:44       9,835 lines
-------------------------------------------
                            1,000,000 lines

This further illustrates the slow-down that occurs.  In just the first
seven minutes, 126,000+ updates are processed.  That's 50% more than
are processed in the final full hour.  When I look closer at the
timestamps, I see a pattern.  Every 7 or so lines, there is a pause or
wait of some sort.  The length of that pause increases over time.  The
length of time between the timestamps for those 7 or so lines stays
relatively consistent -- .002 seconds.  But the lengths of the pauses
increase:

13:00:00  .022 seconds
14:00:00  .104 seconds
15:00:00  .153 seconds
16:00:00  .195 seconds
17:00:00  .225 seconds
18:00:00  .260 seconds

Here's an example from the final hour:

[ 18:00:00.764] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011da.1c, xid: 0x0002.00f.00019952
[ 18:00:00.775] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011da.13c, xid: 0x0002.00f.00019952
[ 18:00:00.777] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011db.6c, xid: 0x0002.00f.00019952
[ 18:00:00.779] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011db.18c, xid: 0x0002.00f.00019952
[ 18:00:00.781] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011dc.bc, xid: 0x0002.00f.00019952
[ 18:00:00.783] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011dc.1dc, xid: 0x0002.00f.00019952
[ 18:00:00.784] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011dd.10c, xid: 0x0002.00f.00019952
[ 18:00:01.042] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011de.3c, xid: 0x0002.00f.00019952
[ 18:00:01.044] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011de.15c, xid: 0x0002.00f.00019952
[ 18:00:01.045] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011df.8c, xid: 0x0002.00f.00019952
[ 18:00:01.047] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011df.1ac, xid: 0x0002.00f.00019952
[ 18:00:01.049] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011e0.dc, xid: 0x0002.00f.00019952
[ 18:00:01.051] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011e1.10, xid: 0x0002.00f.00019952
[ 18:00:01.060] krvss apply 2783: LCR op=3, obj#=2771083, objv 2,
thread 1 rba: 0x0093.000011e1.130, xid: 0x0002.00f.00019952


You can see the pause of .258 seconds between the first seven lines and the next seven. I see nothing in the trace file during the pauses. The timestamps jump directly with nothing in between to indicate what might be happening during the pause.

This is all I have for now.

Mark
--
//www.freelists.org/webpage/oracle-l


Other related posts: