RE: Logical Standby Issues (cont.)
- From: "Bobak, Mark" <Mark.Bobak@xxxxxxxxxxxxxxx>
- To: <strickland.mark@xxxxxxxxx>, <oracle-l@xxxxxxxxxxxxx>
- Date: Fri, 11 Aug 2006 13:09:37 -0400
Hi Mark,
You're way outside my area of expertise, but, is it possible to monitor
the Applier session in V$SESSION_WAIT and see what the waits are that
it's waiting on? Or possibly turn on 10046 trace at level 8 for the
session so that you can see what wait events are affecting the session?
-Mark
--
Mark J. Bobak
Senior Oracle Architect
ProQuest Information & Learning
Ours is the age that is proud of machines that can think and suspicious
of men who try to. --H. Mumford Jones, 1892-1980
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx
[mailto:oracle-l-bounce@xxxxxxxxxxxxx] On Behalf Of Mark Strickland
Sent: Friday, August 11, 2006 1:03 PM
To: oracle-l@xxxxxxxxxxxxx
Subject: 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
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
