When we have two or more processing performing updates, deletes and/or
inserts at the same time our system slows to a crawl.
I was under the impression that Oracle suggests that Redo Log Files be sized
so they switch only every 20 minutes or so. Is the frequency of the log
file switching in the excerpt below normal?
Thread 1 advanced to log sequence 168511
Current log# 1 seq# 168511 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 09:54:58 2008
Thread 1 advanced to log sequence 168512
Current log# 3 seq# 168512 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 10:02:48 2008
Thread 1 advanced to log sequence 168513
Current log# 4 seq# 168513 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 10:10:41 2008
Thread 1 advanced to log sequence 168514
Current log# 2 seq# 168514 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 10:18:35 2008
Thread 1 advanced to log sequence 168515
Current log# 1 seq# 168515 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 11:01:06 2008
Thread 1 advanced to log sequence 168516
Current log# 3 seq# 168516 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 11:21:38 2008
Thread 1 advanced to log sequence 168517
Current log# 4 seq# 168517 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 12:00:06 2008
Thread 1 advanced to log sequence 168518
Current log# 2 seq# 168518 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 12:01:52 2008
Thread 1 advanced to log sequence 168519
Current log# 1 seq# 168519 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 12:03:57 2008
Thread 1 advanced to log sequence 168520
Current log# 3 seq# 168520 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 12:05:14 2008
Thread 1 advanced to log sequence 168521
Current log# 4 seq# 168521 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 12:06:37 2008
Thread 1 advanced to log sequence 168522
Current log# 2 seq# 168522 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 12:07:57 2008
Thread 1 advanced to log sequence 168523
Current log# 1 seq# 168523 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 12:09:27 2008
Thread 1 advanced to log sequence 168524
Current log# 3 seq# 168524 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 12:15:36 2008
Thread 1 advanced to log sequence 168525
Current log# 4 seq# 168525 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 12:42:50 2008
Thread 1 advanced to log sequence 168526
Current log# 2 seq# 168526 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 13:49:29 2008
Thread 1 advanced to log sequence 168527
Current log# 1 seq# 168527 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 13:57:03 2008
Thread 1 advanced to log sequence 168528
Current log# 3 seq# 168528 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 14:00:33 2008
Thread 1 advanced to log sequence 168529
Current log# 4 seq# 168529 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 14:02:38 2008
Thread 1 advanced to log sequence 168530
Current log# 2 seq# 168530 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 14:24:39 2008
Thread 1 advanced to log sequence 168531
Current log# 1 seq# 168531 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 14:29:07 2008
Thread 1 advanced to log sequence 168532
Current log# 3 seq# 168532 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 14:38:32 2008
Thread 1 advanced to log sequence 168533
Current log# 4 seq# 168533 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 14:42:52 2008
Thread 1 advanced to log sequence 168534
Current log# 2 seq# 168534 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 14:50:26 2008
Thread 1 advanced to log sequence 168535
Current log# 1 seq# 168535 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 14:51:47 2008
Thread 1 advanced to log sequence 168536
Current log# 3 seq# 168536 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 14:53:14 2008
Thread 1 advanced to log sequence 168537
Current log# 4 seq# 168537 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 14:54:16 2008
Thread 1 advanced to log sequence 168538
Current log# 2 seq# 168538 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 14:55:43 2008
Thread 1 advanced to log sequence 168539
Current log# 1 seq# 168539 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 14:57:03 2008
Thread 1 advanced to log sequence 168540
Current log# 3 seq# 168540 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 14:58:23 2008
Thread 1 advanced to log sequence 168541
Current log# 4 seq# 168541 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 14:59:31 2008
Thread 1 advanced to log sequence 168542
Current log# 2 seq# 168542 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 15:04:44 2008
Thread 1 advanced to log sequence 168543
Current log# 1 seq# 168543 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 15:06:05 2008
Thread 1 advanced to log sequence 168544
Current log# 3 seq# 168544 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 15:07:30 2008
Thread 1 advanced to log sequence 168545
Current log# 4 seq# 168545 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 15:08:42 2008
Thread 1 advanced to log sequence 168546
Current log# 2 seq# 168546 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 15:10:01 2008
Thread 1 advanced to log sequence 168547
Current log# 1 seq# 168547 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 15:11:21 2008
Thread 1 advanced to log sequence 168548
Current log# 3 seq# 168548 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 15:13:46 2008
Thread 1 advanced to log sequence 168549
Current log# 4 seq# 168549 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 15:17:08 2008
Thread 1 advanced to log sequence 168550
Current log# 2 seq# 168550 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 15:22:31 2008
Thread 1 advanced to log sequence 168551
Current log# 1 seq# 168551 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 15:25:26 2008
Thread 1 advanced to log sequence 168552
Current log# 3 seq# 168552 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 15:50:54 2008
Thread 1 advanced to log sequence 168553
Current log# 4 seq# 168553 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 16:03:25 2008
Thread 1 advanced to log sequence 168554
Current log# 2 seq# 168554 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 16:13:57 2008
Thread 1 advanced to log sequence 168555
Current log# 1 seq# 168555 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 16:25:31 2008
Thread 1 advanced to log sequence 168556
Current log# 3 seq# 168556 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 16:27:17 2008
Thread 1 advanced to log sequence 168557
Current log# 4 seq# 168557 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 16:29:18 2008
Thread 1 advanced to log sequence 168558
Current log# 2 seq# 168558 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 16:31:18 2008
Thread 1 advanced to log sequence 168559
Current log# 1 seq# 168559 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 16:33:20 2008
Thread 1 advanced to log sequence 168560
Current log# 3 seq# 168560 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 16:35:27 2008
Thread 1 advanced to log sequence 168561
Current log# 4 seq# 168561 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 16:37:12 2008
Thread 1 advanced to log sequence 168562
Current log# 2 seq# 168562 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
Tue Jan 22 16:38:35 2008
Thread 1 advanced to log sequence 168563
Current log# 1 seq# 168563 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG1.ORA
Tue Jan 22 16:39:57 2008
Thread 1 advanced to log sequence 168564
Current log# 3 seq# 168564 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
Tue Jan 22 16:57:44 2008
Thread 1 advanced to log sequence 168565
Current log# 4 seq# 168565 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
Tue Jan 22 19:00:16 2008
The 20 minute rule is not based in any type of science, and can be filed
up there with "BCHR must be 99.9 or greater."
Based on your post, there does not seem to be any evidence or reason to
believe that the performance problems are caused by logfile size or
switch frequency. You need to look at the wait events on the database
at the time if the slowdown. If you are on 10g or above, a time-series
history of wait data is available in dba_hist_active_sess_history. Any
conjecture without looking at the waits is just that.
Regards,
Jeremiah Wilton
ORA-600 Consulting
http://www.ora-600.net
> Tue Jan 22 13:57:03 2008
> Thread 1 advanced to log sequence 168528
> Current log# 3 seq# 168528 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG3.ORA
> Tue Jan 22 14:00:33 2008
> Thread 1 advanced to log sequence 168529
> Current log# 4 seq# 168529 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG4.ORA
> Tue Jan 22 14:02:38 2008
> Thread 1 advanced to log sequence 168530
> Current log# 2 seq# 168530 mem# 0: D:\ORACLE\ORADATA\TIERMED\REDO_LOG2.ORA
> Tue Jan 22 14:50:26 2008
> Tue Jan 22 16:25:31 2008
It seems like I recall reading a couple years ago in "Oracle
Performance Tuning 101" by Gaja Krishna Vaidyanatha that redo log
files should switch roughly every 20 minutes under normal processing
loads. Your post above indicates that there are periods in the day
when your log files are switching once every 1 to 2 minutes.
Additional references:
Paraphrased from "Oracle Database Performance Tuning Guide for 10g
R2":
"Generally, larger redo log files provide better performance.
Undersizing log files increases checkpoint activity. Redo log files
in the range of a hundred megabytes to a few gigabytes are considered
reasonable. Switch log files at most every 20 minutes."
Paraphrased from "Expert Oracle Database 10g Administration":
"Redo log files should switch roughly every 20 minutes during a busy
work load and once an hour during normal work loads."
http://jonathanlewis.wordpress.com/2007/04/12/log-file-switch/
"If the intervals are too short (which could cause excessive activity
from the database writer(s) as the log file checkpoint occurs) you can
add new, larger, log files and drop the old ones."
http://jonathanlewis.wordpress.com/2007/10/23/
"log file switch (checkpoint not complete) happens to be a wait time
that can (usually) be eliminated very easily - having more, or bigger,
log files is often all that it takes to avoid the checkpoint
completion issue."
How large are your redo log files, and how many do you have? Take a
close look at the two links above to help determine if the redo log
files need to be resized.
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
It's somewhat correllated with the granularity of restoration. If you
are getting your arcs and backups away from the computer (or the disk
drive with your data files on it) and it gets nuked, this controls how
much data you've lost. You don't have to lose any data at all if you
can protect the unarchived redo.
The science comes in when you define the uptime requirements or
service level agreement.
(I speculate the rule came from before there was a checkpoint process
and a typical configuration was VMS with a few disks, so you didn't
want a long running checkpoint to interfere with a long running
archive copy. Now it has attained mythic status, but still is not
unreasonable as a ballpark setting before more specific tuning).
>
> Based on your post, there does not seem to be any evidence or reason to
> believe that the performance problems are caused by logfile size or
> switch frequency. You need to look at the wait events on the database
> at the time if the slowdown. If you are on 10g or above, a time-series
> history of wait data is available in dba_hist_active_sess_history. Any
> conjecture without looking at the waits is just that.
True, but there can be an impact if the archiving I/O interferes with
normal db I/O, which can happen on many configurations - certainly a
possibility if you don't have a lot of controllers, and likely if you
have just one disk device apparent to Oracle on a Windows box.
The sequential read and write characteristics of copying redo can have
quite an effect on a RAID-5 fighting with random reads and writes to
data and undo, performance goes to hell when any of the various device
buffers are saturated.
Of course, the waits will tell if it is I/O or block contention in the
SGA or whatall. The alert log shown doesn't seem to have checkpoint
messages, so that's good. But we haven't seen that there aren't any
times when there are such messages.
>
> Regards,
>
> Jeremiah Wilton
> ORA-600 Consultinghttp://www.ora-600.net
jg
--
@home.com is bogus.
Nobody knows what's going on, so reinstall everything:
http://www.linux.com/feature/125548
> On Jan 23, 6:21 pm, Jeremiah Wilton <jerem...@ora-600.net> wrote:
>
>> Dereck L. Dietz wrote:
>>
>>> I was under the impression that Oracle suggests that Redo Log Files be sized
>>> so they switch only every 20 minutes or so.
>>
>> The 20 minute rule is not based in any type of science...
>
> It's somewhat correllated with the granularity of restoration. If you
> are getting your arcs and backups away from the computer (or the disk
> drive with your data files on it) and it gets nuked, this controls how
> much data you've lost. You don't have to lose any data at all if you
> can protect the unarchived redo.
With modern versions of Oracle, log shipping can be done asynchronously
for the current online redolog, so we no longer have to wait for log
switch to be assured of the presence of contemporary redo at the remote
archive site. Hopefully for most people, forcing frequent log switches
is not an issue thanks to this feature.
Assuming someone were not using LGWR ASYNC for some reason, wouldn't the
original poster's frequent log switching provide *more* recent log data
at a hypothetical remote log shipping site?
> (I speculate the rule came from before there was a checkpoint process
> and a typical configuration was VMS with a few disks, so you didn't
> want a long running checkpoint to interfere with a long running
> archive copy.
Oddly, the CKPT process doesn't perform checkpointing. I think this is
quite funny. CKPT performs datafile header and controlfile writes upon
checkpoint completion. Before CKPT, this was LGWR's job, so all commits
stopped while header/controlfile SCNs were written. DBWn perform
checkpoint I/O as a proportion of the DBWR write batch as they always
have. This proportion and the currency of the checkpoint is now
demand-based when using FAST_START_MTTR_TARGET.
> Now it has attained mythic status, but still is not
> unreasonable as a ballpark setting before more specific tuning).
I suppose, but the whole idea that log swicthes have anything to do with
the OP's performance problem is complete and total conjecture. Why are
we even talking about log switches when we don't know what the
predominant waits are? Many I/O subsystems will provide excellent
performance despite log switches every couple minutes. It just depends
too much on the underlying storage performance to continue proliferating
blind rules of thumb on any Oracle metric.
>> Based on your post, there does not seem to be any evidence or reason to
>> believe that the performance problems are caused by logfile size or
>> switch frequency. You need to look at the wait events on the database
>> at the time if the slowdown. If you are on 10g or above, a time-series
>> history of wait data is available in dba_hist_active_sess_history. Any
>> conjecture without looking at the waits is just that.
>
> True, but there can be an impact if the archiving I/O interferes with
> normal db I/O, which can happen on many configurations - certainly a
> possibility if you don't have a lot of controllers, and likely if you
> have just one disk device apparent to Oracle on a Windows box.
Yes, I/O contention might be a problem... but there is absolutely no
evidence to lead anyone to believe that is the case. It is just as
possible that there is enqueue contention for a single row of data, but
that's just conjecture too. It could be anything. I don't see what we
get out of propping up this theory without data.