Re: Logical Standby Issues (cont.)

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

--
http://www.freelists.org/webpage/oracle-l