'control file sequential read' high average time

#1

Db version 11.2.0.2
Physical standby : LGWR ASYNC
Database on ASM.
Application Oracle EBS
Redo log files : 5 groups with 2 members each 500M
Log switches: every 5 minutes

During stress tests with about 2000 users the statistic 'user commits'
of v$sysstat shows about 250 commits and rollbacks per second.
The average time for 'log file sync' starts to increase until it
reaches 490.000 usec per occurence from about 1.000 usec during off
peak hours. The
The average time for 'log file parallel write' increases to about
2.200 usec from about 700 usec during off peak hours.
When looking in dba_hist_active_sess_history the event that occurs for
the log writer process is 'control file sequential read' with about
90% of the total wait time.
During the same time frame the average time for 'control file
sequential read' increases to about 13.000 usec from about 45 usec
during off peak hours.

I am trying to figure out why there is an about 500 fold increase of
the log file sync event.
Could it have to do with the standby?
Is the number of commits per second too high?

Any clues?

Regards HansP

#2

On Mon, 29 Aug 2011 06:18:11 -0700, HansP wrote:

Quote:

Db version 11.2.0.2
Physical standby : LGWR ASYNC
Database on ASM.
Application Oracle EBS
Redo log files : 5 groups with 2 members each 500M Log switches: every 5
minutes

During stress tests with about 2000 users the statistic 'user commits'
of v$sysstat shows about 250 commits and rollbacks per second. The
average time for 'log file sync' starts to increase until it reaches
490.000 usec per occurence from about 1.000 usec during off peak hours.
The
The average time for 'log file parallel write' increases to about 2.200
usec from about 700 usec during off peak hours. When looking in
dba_hist_active_sess_history the event that occurs for the log writer
process is 'control file sequential read' with about 90% of the total
wait time.
During the same time frame the average time for 'control file sequential
read' increases to about 13.000 usec from about 45 usec during off peak
hours.

I am trying to figure out why there is an about 500 fold increase of the
log file sync event.
Could it have to do with the standby? Is the number of commits per
second too high?

Any clues?

Regards HansP

I have the same problem, only different application. EBS doesn't have
much to do with this. This an ASH bug, described in the MoS document
941761.1. To my knowledge, this isn't fixed yet.

--
http://mgogala.byethost5.com

#3

On Aug 29, 11:09*am, Mladen Gogala <gogala.mla... (AT) gmail (DOT) com> wrote:

Quote:

On Mon, 29 Aug 2011 06:18:11 -0700, HansP wrote:
Db version 11.2.0.2
Physical standby : LGWR ASYNC
Database on ASM.
Application Oracle EBS
Redo log files : 5 groups with 2 members each 500M Log switches: every 5
minutes

During stress tests with about 2000 users the statistic 'user commits'
of v$sysstat shows about 250 commits and rollbacks per second. The
average time for 'log file sync' starts to increase until it reaches
490.000 usec per occurence from about 1.000 usec during off peak hours.
The
The average time for 'log file parallel write' increases to about 2.200
usec from about 700 usec during off peak hours. When looking in
dba_hist_active_sess_history the event that occurs for the log writer
process is 'control file sequential read' with about 90% of the total
wait time.
During the same time frame the average time for 'control file sequential
read' increases to about 13.000 usec from about 45 usec during off peak
hours.

I am trying to figure out why there is an about 500 fold increase of the
log file sync event.
Could it have to do with the standby? Is the number of commits per
second too high?

Any clues?

Regards HansP

I have the same problem, only different application. EBS doesn't have
much to do with this. This an ASH bug, described in the MoS document
941761.1. To my knowledge, this isn't fixed yet.

--http://mgogala.byethost5.com- Hide quoted text -

- Show quoted text -

Apparently there is a one-off patch for the listed bug (8682160) as
listed in the above-mentioned document from MoS.

David Fitzjarrell

#4

On Mon, 29 Aug 2011 13:15:39 -0700, ddf wrote:

Quote:

Apparently there is a one-off patch for the listed bug (8682160) as
listed in the above-mentioned document from MoS.

Hmmmm, the analyst told me that it isn't available for 32 bit Linux. I'll
have to check again.

--
http://mgogala.byethost5.com

#5

On Aug 29, 2:34*pm, Mladen Gogala <gogala.mla... (AT) gmail (DOT) com> wrote:

Quote:

On Mon, 29 Aug 2011 13:15:39 -0700, ddf wrote:
Apparently there is a one-off patch for the listed bug (8682160) as
listed in the above-mentioned document from MoS.

Hmmmm, the analyst told me that it isn't available for 32 bit Linux. I'll
have to check again.

--http://mgogala.byethost5.com

Don't bother -- it's for 11.1.0.7, not 11.2.0.2.

David Fitzjarrell

#6

On Mon, 29 Aug 2011 15:01:11 -0700, ddf wrote:

Quote:

Don't bother -- it's for 11.1.0.7, not 11.2.0.2.

Thanks David. I believe that the original poster now has a better idea
about the problem. In my opinion, 11.2 is a fairly good release, despite
some bugs. Interestingly enough, the most welcome news for me is the
possibility to open a standby as a snapshot and test the applications. It
makes the logistics of doing UAT so much easier. As for the bugs, life
would be so much less interesting without them....

--
http://mgogala.byethost5.com

#7

Is any other process reading the control file ?
Is any other process writing to the control file ?
Does the event histogram show a normal distribution or a skew
Are the rollbacks "user rollbacks" only, or "transaction rollback" as well.

--
Regards

Jonathan Lewis
http://jonathanlewis.wordpress.com

"HansP" <Hans-Peter.Sloot (AT) atosorigin (DOT) com> wrote

Quote:

Db version 11.2.0.2
Physical standby : LGWR ASYNC
Database on ASM.
Application Oracle EBS
Redo log files : 5 groups with 2 members each 500M
Log switches: every 5 minutes

During stress tests with about 2000 users the statistic 'user commits'
of v$sysstat shows about 250 commits and rollbacks per second.
The average time for 'log file sync' starts to increase until it
reaches 490.000 usec per occurence from about 1.000 usec during off
peak hours. The
The average time for 'log file parallel write' increases to about
2.200 usec from about 700 usec during off peak hours.
When looking in dba_hist_active_sess_history the event that occurs for
the log writer process is 'control file sequential read' with about
90% of the total wait time.
During the same time frame the average time for 'control file
sequential read' increases to about 13.000 usec from about 45 usec
during off peak hours.

I am trying to figure out why there is an about 500 fold increase of
the log file sync event.
Could it have to do with the standby?
Is the number of commits per second too high?

#8

On 30 aug, 00:24, "Jonathan Lewis" <jonat... (AT) jlcomp (DOT) demon.co.uk>
wrote:

Quote:

Is any other process reading the control file ?
Is any other process writing to the control file ?
Does the event histogram show a normal distribution or a skew
Are the rollbacks "user rollbacks" only, or "transaction rollback" as well.

--
Regards

Jonathan Lewishttp://jonathanlewis.wordpress.com

On 30 aug, 00:24, "Jonathan Lewis" <jonat... (AT) jlcomp (DOT) demon.co.uk

wrote:

Quote:

Is any other process reading the control file ?
Is any other process writing to the control file ?
Does the event histogram show a normal distribution or a skew
Are the rollbacks "user rollbacks" only, or "transaction rollback" as well.

Yes other proceses are reading the controlfile. When looking in

dba_his_active_sess_history I see that an OMS from GridControl is
doing slightly more reads than the LGWR. In 3rd place is the CKPT
background process.

Writing to the controlfile is done mainly by the CKPT process. Some
other processes (5) are writing too but the number of writes is very
low (< 2% of the total number).

In my opinion the event histograms is skewed.
snap_id begin_interval_time wait_time_milli count
974 2011-08-25 16:49:57 1 9723
974 2011-08-25 16:49:57 2 7345
974 2011-08-25 16:49:57 4 5779
974 2011-08-25 16:49:57 8 5339
974 2011-08-25 16:49:57 16 6097
974 2011-08-25 16:49:57 32 6297
974 2011-08-25 16:49:57 64 6205
974 2011-08-25 16:49:57 128 4509
974 2011-08-25 16:49:57 256 2746
974 2011-08-25 16:49:57 512 1128
974 2011-08-25 16:49:57 1024 884
974 2011-08-25 16:49:57 2048 1293
974 2011-08-25 16:49:57 4096 3052
974 2011-08-25 16:49:57 8192 2662

What do you mean with your last question?

regards HansP

#9

Quote:

I have the same problem, only different application. EBS doesn't have
much to do with this. This an ASH bug, described in the MoS document
941761.1. To my knowledge, this isn't fixed yet.

--http://mgogala.byethost5.com

Hello Mladen,
I had seen the Note already.
But I have doubt whether the issue described there applies to my
situation.
I do not see inserts on wr$ or wrh$ tables taking a lot of time. And
the MMNL is not one of the top sessions.

regards Hans-Peter

#10

On Tue, 30 Aug 2011 03:12:18 -0700, HansP wrote:

Quote:

I have the same problem, only different application. EBS doesn't have
much to do with this. This an ASH bug, described in the MoS document
941761.1. To my knowledge, this isn't fixed yet.

--http://mgogala.byethost5.com

Hello Mladen,
I had seen the Note already.
But I have doubt whether the issue described there applies to my
situation.
I do not see inserts on wr$ or wrh$ tables taking a lot of time. And the
MMNL is not one of the top sessions.

regards Hans-Peter

I am not sure what is the platform but you could monitor the access to
control files by using systemtap or dtrace. These utilities could tell
you not only who is doing I/O against the files but also what is being
written or read. I will take a back seat and let Jonathan sort this one
out, if he can.

--
http://mgogala.byethost5.com