Not so sure your last statement about sizing at 25M is a good one. Isnt that a bit of a broad statement as you arent taking into account the size/throughput of the database. Everything else makes sense but you could be giving people a bumb steer with that size?

I try and aim at log switches every 20 minutes and never below 5 minutes during highest batch updates. This needs a size of 350Mb per redo log on the DB's i work on. I typically use 6 redo log groups. Am i doing something wrong in this?

Hello TOM
I got more database problems at different customer places. Today is not good day. I'm getting the same error like above. I think i have to increase the log_buffer, Log_checkpoint_interval and log_checkpoint_timeout. But you told in the other question that we have to drop the log file and create it. Will it effect existing database and how we can do it?. Can you pl give me the steps?.

Entry from alert.log:

Mon Mar 18 08:20:42 2002
Thread 1 advanced to log sequence 20021
Current log# 1 seq# 20021 mem# 0: /opt/oracle/dbs/oradata/mangdbs/redo01.log
Mon Mar 18 08:21:15 2002
Thread 1 cannot allocate new log, sequence 20022
Checkpoint not complete
Current log# 1 seq# 20021 mem# 0: /opt/oracle/dbs/oradata/mangdbs/redo01.log
Thread 1 advanced to log sequence 20022
Current log# 2 seq# 20022 mem# 0: /opt/oracle/dbs/oradata/mangdbs/redo02.log
Mon Mar 18 08:21:50 2002
Thread 1 cannot allocate new log, sequence 20023
Checkpoint not complete
Current log# 2 seq# 20022 mem# 0: /opt/oracle/dbs/oradata/mangdbs/redo02.log
Thread 1 advanced to log sequence 20023
Current log# 1 seq# 20023 mem# 0: /opt/oracle/dbs/oradata/mangdbs/redo01.log
Mon Mar 18 08:24:14 2002
Thread 1 cannot allocate new log, sequence 20024
Checkpoint not complete


Entry from init.ora:

db_block_buffers = 8192
db_block_size = 2048
shared_pool_size = 125000000
large_pool_size=62914560
log_archive_start = FALSE
log_buffer = 163840
log_checkpoint_interval=10000
lock_checkpoint_timeout=1800

Is it possible to increase this way..

log_buffer = 2163840
log_checkpoint_interval=10000
lock_checkpoint_timeout=1800

Thanks in advance.

regards,
sivababu

Tom,

I wonder if you could clarify something for me regarding the "cannot allocate new log" message. From our alert log (see below), it seems that log#2 would have been available for Oracle to use. Instead, our system grinds to a halt until a checkpoint completes.

Alert Log Snippet (blank lines added for clarity):
----------------------------------------------------

Tue Feb 25 03:42:29 2003
Beginning log switch checkpoint up to RBA [0x19ff.2.10], SCN: 0x0000.644a08a2
Thread 1 advanced to log sequence 6655
Current log# 1 seq# 6655 mem# 0: /redo01/oradata/eisp/redo1a.log
Current log# 1 seq# 6655 mem# 1: /redo02/oradata/eisp/redo1b.log

Tue Feb 25 03:42:29 2003
ARC0: Beginning to archive log# 3 seq# 6654

Tue Feb 25 03:43:08 2003
ARC0: Completed archiving log# 3 seq# 6654

Tue Feb 25 04:11:27 2003
Beginning log switch checkpoint up to RBA [0x1a00.2.10], SCN: 0x0000.644a1165
Thread 1 advanced to log sequence 6656
Current log# 2 seq# 6656 mem# 0: /redo01/oradata/eisp/redo2a_NEW.log
Current log# 2 seq# 6656 mem# 1: /extra01/oradata/eisp/redo2b.log

Tue Feb 25 04:11:27 2003
ARC0: Beginning to archive log# 1 seq# 6655

Tue Feb 25 04:11:55 2003
ARC0: Completed archiving log# 1 seq# 6655

Tue Feb 25 04:19:39 2003
Completed checkpoint up to RBA [0x19ff.2.10], SCN: 0x0000.644a08a2

Tue Feb 25 05:00:05 2003
Completed checkpoint up to RBA [0x1a00.2.10], SCN: 0x0000.644a1165

Tue Feb 25 05:06:35 2003
Beginning log switch checkpoint up to RBA [0x1a01.2.10], SCN: 0x0000.644a1dbb
Thread 1 advanced to log sequence 6657
Current log# 3 seq# 6657 mem# 0: /redo02/oradata/eisp/redo3a.log
Current log# 3 seq# 6657 mem# 1: /extra01/oradata/eisp/redo3b.log

Tue Feb 25 05:06:35 2003
ARC0: Beginning to archive log# 2 seq# 6656

Tue Feb 25 05:07:00 2003
ARC0: Completed archiving log# 2 seq# 6656

Tue Feb 25 05:51:12 2003
Beginning log switch checkpoint up to RBA [0x1a02.2.10], SCN: 0x0000.644a251e
Thread 1 advanced to log sequence 6658
Current log# 1 seq# 6658 mem# 0: /redo01/oradata/eisp/redo1a.log
Current log# 1 seq# 6658 mem# 1: /redo02/oradata/eisp/redo1b.log

Tue Feb 25 05:51:12 2003
ARC0: Beginning to archive log# 3 seq# 6657

Tue Feb 25 05:51:35 2003
ARC0: Completed archiving log# 3 seq# 6657

Tue Feb 25 06:39:05 2003
Thread 1 cannot allocate new log, sequence 6659
Checkpoint not complete
Current log# 1 seq# 6658 mem# 0: /redo01/oradata/eisp/redo1a.log
Current log# 1 seq# 6658 mem# 1: /redo02/oradata/eisp/redo1b.log

Tue Feb 25 06:56:30 2003
Completed checkpoint up to RBA [0x1a01.2.10], SCN: 0x0000.644a1dbb

Tue Feb 25 06:56:30 2003
Beginning log switch checkpoint up to RBA [0x1a03.2.10], SCN: 0x0000.644a2b29
Thread 1 advanced to log sequence 6659
Current log# 2 seq# 6659 mem# 0: /redo01/oradata/eisp/redo2a_NEW.log
Current log# 2 seq# 6659 mem# 1: /extra01/oradata/eisp/redo2b.log

****************************************
As soon as a checkpoint was completed for [0x1a01.2.10], then log# 2 was able to be allocated. If I am reading the log correctly, it was not doing anything anyway so why could it not be used prior to the checkpoint completing? I'm matching up the "beginning log switch checkpoint up to RBA [xxxx]" with the "completed checkpoint up to RBA [xxxx]" to see that #1 and #3 were busy, but what was #2 doing that it could not be allocated? I think I'm repeating myself...

Thanks for any insight,
David

My database runs on OPS, redo log size is 8M, could you please tell me why archive log file even increase (about 4-6 minutes) when my database has no user connect to whole day. How can I check my database is running on load balancing mode.

Tom,
I have 2 database, one runs on 8i OPS and the other runs on 8i (no OPS). When no user connect to, database runs on OPS genarates 1 archivelog file per 4-6 minutes. I analyse archivelog files and select from v$logmnr_contents:

SQLWKS> SELECT operation,count(*) FROM v$logmnr_contents group by operation
2>
OPERATION COUNT(*)
-------------------------------- ----------
COMMIT 8696
DELETE 5
INSERT 5
INTERNAL 17903
START 8697
UPDATE 30
6 rows selected.

When no user connect to, database runs on 8i (no OPS) genarates only 1 archivelog file when database startup.
Could you explain the difference.

Thanks so much! I was thinking the "Beginning checkpoint..." applied to the log number on the next line in the alert log. I now see that all three logs were "busy".

Our log_checkpoint_interval is 1000000 blocks and, yes, our disks are raid 5. Changing the raid is possible long term. In the near term we are going to try reducing the size of the logs (256MB) and maybe shorten the checkpoint interval...

Tom,
Great explaination of the alert log

Nicely done

Dear Tom:

FYI, with the advent of Oracle-managed files, I have submitted Enhancement Request No. 3004256 to create a new redo logfile group in the case of checkpoint or archive not completed. We'll see if it is accepted for a future release.

Best regards,

In your book, you mention that Log Writer is useful to improve the performance since it does sequnetial writing. Using only DBWR (non-sequential writing) will degrade the performance.

But, as I understand, the "checkpoint not complete, cannot allocate new log", error *indicates* "DBWR cannot compete with LGWR".

Where do I fail to understand ?

You said

"the checkpoint not complete indicates that dbwr was not keeping up with lgwr and
is generally caused by undersizing your log files (or number thereof) "

I understand that they do totally diffeent works, but, LGWR has to wait for DBWR to complete. What I was refering the *only* benifit of sequential writing by the LGWR.

Suppose there are 10 Log files. By making it 100 or even 1000 does not guarantee that the error would not occur.
At some point, sooner or later, DBWR has to go ahead of LGWR.

Tom


I ran an update during the day which took 5hrs 45 mins to complete. It finished at 6 pm and our cold backup didn't kick in until 3am the
next morning. When i got in the next day i noticed that there were lots of messages like:

"...Thread 1 cannot allocate new log, sequence 177759...."


in the alert log, which i gather is from redo logs not being large enough (we don't normally get this).
I assume this was due to the disk intensive update i was running that day?

But also the database shutdown immediate began at 3am and didn't finish til 4.45am. Can you shed some light on why this
would happen if the update finished at 6pm the previous evening?

The relevant parts of the ALERT log are listed below:




Mon Dec 1 18:03:04 2003
Thread 1 cannot allocate new log, sequence 177753
Checkpoint not complete
Current log# 1 seq# 177752 mem# 0: /general/oradata/OP3/redo_1.log
Current log# 1 seq# 177752 mem# 1: /tmptblsp/OP3/logfile/redo_2.log Mon Dec 1 18:03:26 2003 Thread 1 advanced to log sequence 177753
Current log# 4 seq# 177753 mem# 0: /general/oradata/OP3/redo_7.log
Current log# 4 seq# 177753 mem# 1: /tmptblsp/OP3/logfile/redo_8.log Mon Dec 1 18:03:26 2003
ARC0: Beginning to archive log# 1 seq# 177752
Mon Dec 1 18:03:39 2003
ARC0: Completed archiving log# 1 seq# 177752
Mon Dec 1 18:03:43 2003
Thread 1 cannot allocate new log, sequence 177754
Checkpoint not complete
Current log# 4 seq# 177753 mem# 0: /general/oradata/OP3/redo_7.log
Current log# 4 seq# 177753 mem# 1: /tmptblsp/OP3/logfile/redo_8.log Mon Dec 1 18:04:09 2003 Thread 1 advanced to log sequence 177754
Current log# 5 seq# 177754 mem# 0: /general/oradata/OP3/redo_9.log
Current log# 5 seq# 177754 mem# 1: /tmptblsp/OP3/logfile/redo_10.log Mon Dec 1 18:04:09 2003
ARC0: Beginning to archive log# 4 seq# 177753
Mon Dec 1 18:04:21 2003
ARC0: Completed archiving log# 4 seq# 177753
Tue Dec 2 03:00:02 2003
Restarting dead background process EMN0
EMN0 started with pid=16
Tue Dec 2 03:00:07 2003
Shutting down instance (immediate)
License high water mark = 45
Tue Dec 2 03:00:10 2003
ALTER DATABASE CLOSE NORMAL
Tue Dec 2 03:00:14 2003
ARC0: Beginning to archive log# 5 seq# 177754
Tue Dec 2 03:00:14 2003
Thread 1 advanced to log sequence 177755
Current log# 2 seq# 177755 mem# 0: /general/oradata/OP3/redo_3.log
Current log# 2 seq# 177755 mem# 1: /tmptblsp/OP3/logfile/redo_4.log Tue Dec 2 03:00:21 2003
ARC0: Completed archiving log# 5 seq# 177754
Tue Dec 2 03:00:22 2003
Thread 1 advanced to log sequence 177756
Current log# 3 seq# 177756 mem# 0: /general/oradata/OP3/redo_5.log
Current log# 3 seq# 177756 mem# 1: /tmptblsp/OP3/logfile/redo_6.log Tue Dec 2 03:00:22 2003
ARC0: Beginning to archive log# 2 seq# 177755
ARC0: Completed archiving log# 2 seq# 177755
Tue Dec 2 03:00:34 2003
Thread 1 advanced to log sequence 177757
Current log# 1 seq# 177757 mem# 0: /general/oradata/OP3/redo_1.log
Current log# 1 seq# 177757 mem# 1: /tmptblsp/OP3/logfile/redo_2.log Tue Dec 2 03:00:34 2003
ARC0: Beginning to archive log# 3 seq# 177756
ARC0: Completed archiving log# 3 seq# 177756
Tue Dec 2 03:00:46 2003
Thread 1 advanced to log sequence 177758
Current log# 4 seq# 177758 mem# 0: /general/oradata/OP3/redo_7.log
Current log# 4 seq# 177758 mem# 1: /tmptblsp/OP3/logfile/redo_8.log Tue Dec 2 03:00:46 2003
ARC0: Beginning to archive log# 1 seq# 177757

ARC0: Completed archiving log# 1 seq# 177757
Tue Dec 2 03:00:59 2003
Thread 1 cannot allocate new log, sequence 177759
Checkpoint not complete
Current log# 4 seq# 177758 mem# 0: /general/oradata/OP3/redo_7.log
Current log# 4 seq# 177758 mem# 1: /tmptblsp/OP3/logfile/redo_8.log Tue Dec 2 03:01:09 2003 Thread 1 advanced to log sequence 177759
Current log# 5 seq# 177759 mem# 0: /general/oradata/OP3/redo_9.log
Current log# 5 seq# 177759 mem# 1: /tmptblsp/OP3/logfile/redo_10.log Tue Dec 2 03:01:09 2003
ARC0: Beginning to archive log# 4 seq# 177758
ARC0: Completed archiving log# 4 seq# 177758
Tue Dec 2 03:01:20 2003
Thread 1 cannot allocate new log, sequence 177760
Checkpoint not complete
Current log# 5 seq# 177759 mem# 0: /general/oradata/OP3/redo_9.log
Current log# 5 seq# 177759 mem# 1: /tmptblsp/OP3/logfile/redo_10.log Tue Dec 2 03:01:41 2003 Thread 1 advanced to log sequence 177760
Current log# 2 seq# 177760 mem# 0: /general/oradata/OP3/redo_3.log
Current log# 2 seq# 177760 mem# 1: /tmptblsp/OP3/logfile/redo_4.log Tue Dec 2 03:01:41 2003
ARC0: Beginning to archive log# 5 seq# 177759
ARC0: Completed archiving log# 5 seq# 177759
Tue Dec 2 03:01:51 2003

...
...
...continues with these type of messages until:
...
...
...

Tue Dec 2 04:37:19 2003
Thread 1 cannot allocate new log, sequence 177836
Checkpoint not complete
Current log# 2 seq# 177835 mem# 0: /general/oradata/OP3/redo_3.log
Current log# 2 seq# 177835 mem# 1: /tmptblsp/OP3/logfile/redo_4.log Tue Dec 2 04:37:30 2003 Thread 1 advanced to log sequence 177836
Current log# 3 seq# 177836 mem# 0: /general/oradata/OP3/redo_5.log
Current log# 3 seq# 177836 mem# 1: /tmptblsp/OP3/logfile/redo_6.log Tue Dec 2 04:37:30 2003
ARC0: Beginning to archive log# 2 seq# 177835
ARC0: Completed archiving log# 2 seq# 177835
Tue Dec 2 04:38:12 2003
Thread 1 cannot allocate new log, sequence 177837
Checkpoint not complete
Current log# 3 seq# 177836 mem# 0: /general/oradata/OP3/redo_5.log
Current log# 3 seq# 177836 mem# 1: /tmptblsp/OP3/logfile/redo_6.log Thread 1 advanced to log sequence 177837
Current log# 1 seq# 177837 mem# 0: /general/oradata/OP3/redo_1.log
Current log# 1 seq# 177837 mem# 1: /tmptblsp/OP3/logfile/redo_2.log Tue Dec 2 04:38:19 2003
ARC0: Beginning to archive log# 3 seq# 177836
ARC0: Completed archiving log# 3 seq# 177836
Tue Dec 2 04:38:47 2003
SMON: disabling tx recovery
SMON: disabling cache recovery
Tue Dec 2 04:41:08 2003
Thread 1 closed at log sequence 177837
Tue Dec 2 04:41:11 2003
Completed: ALTER DATABASE CLOSE NORMAL
Tue Dec 2 04:41:12 2003
ALTER DATABASE DISMOUNT
Completed: ALTER DATABASE DISMOUNT
archiving is disabled
Tue Dec 2 04:41:13 2003
ARCH shutting down
ARC0: Archival stopped



Could this have been due to the transaction being uncommitted and thus all the activity on shutdown was actually the
db trying to rollback?

Hi

I see checkpoint not complete msg in my alert:

Thread 1 advanced to log sequence 637
Current log# 8 seq# 637 mem# 0: /u02/oradata/SIMP/redo01/redo08_a.log
Current log# 8 seq# 637 mem# 1: /u03/oradata/SIMP/redo02/redo08_b.log
Thu Jul 22 15:16:57 2004
ARC1: Evaluating archive log 7 thread 1 sequence 636
Thu Jul 22 15:16:57 2004
SIMP; ARC1: Beginning to archive log 7 thread 1 sequence 636 (0.320627198:0.320650582)
ARCH: Connecting to console port...
Thu Jul 22 15:16:57 2004
SIMP; ARC1: Creating local archive destination LOG_ARCHIVE_DEST_1: '/u03/oradata/SIMP/arch/SIMP_531695692_1_636.arc' (thread 1 sequence 636)
ARCH: Connecting to console port...
Thu Jul 22 15:16:57 2004
SIMP; ARC1: Closing local archive destination LOG_ARCHIVE_DEST_1: '/u03/oradata/SIMP/arch/SIMP_531695692_1_636.arc'
ARCH: Connecting to console port...
Committing creation of archivelog '/u03/oradata/SIMP/arch/SIMP_531695692_1_636.arc'
Thu Jul 22 15:16:57 2004
SIMP; ARC1: Completed archiving log 7 thread 1 sequence 636
ARCH: Connecting to console port...
Thu Jul 22 16:29:53 2004
Thread 1 cannot allocate new log, sequence 638
Checkpoint not complete
Current log# 8 seq# 637 mem# 0: /u02/oradata/SIMP/redo01/redo08_a.log
Current log# 8 seq# 637 mem# 1: /u03/oradata/SIMP/redo02/redo08_b.log

The thing is if I see my log history my last log switch is 1 hour ago so how can I get this message?

634 532188010 1 634 320590412 20040722 13:44:09 320618825 1 20040716 21:14:52
635 532188863 1 635 320618825 20040722 14:00:10 320627198 1 20040716 21:14:52
636 532192617 1 636 320627198 20040722 14:14:23 320650582 1 20040716 21:14:52
637 532196995 1 637 320650582 20040722 15:16:57 320693752 1 20040716 21:14:52
638 532198486 1 638 320693752 20040722 16:29:55 320704883 1 20040716 21:14:52
639 532198500 1 639 320704883 20040722 16:54:46 320708220 1 20040716 21:14:52

Are my checkpoints taking over one hour?!

Hi

the redo logs are 50mb not 500mb!

Sorry should have posted the query!

select * from v$log_history where sequence# between 632 and 640;

RECID STAMP THREAD# SEQUENCE# FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# RESETLOGS_CHANGE# RESETLOGS_TIME
---------- ---------- ---------- ---------- ------------- ----------------- ------------ ----------------- -----------------
632 532184671 1 632 320529820 20040722 12:28:19 320557098 1 20040716 21:14:52
633 532187049 1 633 320557098 20040722 13:04:31 320590412 1 20040716 21:14:52
634 532188010 1 634 320590412 20040722 13:44:09 320618825 1 20040716 21:14:52
635 532188863 1 635 320618825 20040722 14:00:10 320627198 1 20040716 21:14:52
636 532192617 1 636 320627198 20040722 14:14:23 320650582 1 20040716 21:14:52
637 532196995 1 637 320650582 20040722 15:16:57 320693752 1 20040716 21:14:52
638 532198486 1 638 320693752 20040722 16:29:55 320704883 1 20040716 21:14:52
639 532198500 1 639 320704883 20040722 16:54:46 320708220 1 20040716 21:14:52
640 532198516 1 640 320708220 20040722 16:55:00 320711583 1 20040716 21:14:52

9 rows selected.


It was STAMP.

So I am puzzled how can a checkpoint take one hoourr

This is 10g btw

rgds

Hi

I have 8 groups of 50mb redologs!

Guess 16 will do

thx

I have this to achive incremental checkpoints

fast_start_mttr_target integer 1200

not good enough? :-?

Tom,
I’ve read the concepts manual on the DBWR, LGWR, CKPT background processes about 3 times before posting this question :). I still find it a little hard to grasp as to why checkpoints take very long sometimes.

From what I understand, 1) DBWRs usually do a good job in flushing dirty buffers to disk. One could ofcourse configure multiple DBWRs if they see a need. 2) LGWRs also seem to do a good job of flushing from redo buffers to redolog files. It is the checkpointing process (either using CKPT or LGWR) that is invariably the real bottleneck. But why??

Checkpoints “merely” update file headers with updated SCNs upon a commit – correct? I realize that it is proportional to number of datafiles, io/disk speed. But conceptually, I don’t understand why it should take “very long” sometimes to update a few datafiles (say 100), controlfiles with a few SCNs? I can understand if every data block had something that had to be updated with this information. But that isn’t the case – right? Just the datafile headers and controlfiles get updated with the new SCN. The data has already been flushed to disk (the individual data blocks) by the DBWR. So why the big “delay” now to just update file headers? Even if the disks were really slow, why should it take all that long??

Thanks for your time.

lgwr signals a checkpoint,

dbwr is the main checkpoint process, ckpt has the relatively simple job of updating file headers.

dbwr is invariably the bottleneck in a checkpoint.


checkpoints flush the blocks in the buffer cache that are protected by redo.  if you generate 50meg of redo -- you might be protecting thousands and thousands of blocks in the buffer cache.  before we can reuse that 50meg redo log file -- we must flush to disk all of those thousands of dirty blocks.

remember:

  update t set indexed_number_column = 0 where primary_key = 1;

updates a single row and generates very little redo (lets say 228 bytes for grins 

ops$tkyte@ORA9IR2> update t set x = 0 where pk = 1;
 
1 row updated.
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          1  db block gets
          1  consistent gets
          0  physical reads
        228  redo size
        784  bytes sent via SQL*Net to client
        800  bytes received via SQL*Net from client
          4  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processed
 


(just enough redo to say "change indexed_number_column to zero for rowid "x").

but -- in the buffer cache, we have just

a) changed an 8k table block that will need to be written
b) maybe caused a row migration (update a null to a non-null) so we might 
   have 2 8k table blocks
c) updated perhaps 2 index leaf blocks (column was 1000000000000000, is now 0, 
   index entry moved from the right to the left.
d) maybe caused a split up an index -- say 2 more blocks.


so that measely 228 bytes of redo might be protecting 4 8k blocks (32k of data) that dbwr must flush out at some point.

this is why we use redo -- instead of just writing to the datafiles when you commit.  we can write 228 bytes sequentially to the log files -- instead of writing 32k of data out using random IO (lots of seeking around)


the checkpoint writes out all of these dirty blocks -- that is what takes so "long" 

Tom,
Thanks for the response. So, DBWR is the essentially culprit. And I used to think (wrongly?) that DBWR was intelligent enough to know ‘when to flush’ to disk in order to generate optimal performance. But that isn't the case.

When a massive update/delete happens, I conclude from your response that DBWR lazily appears to sit there doing nothing, while the LGWR works fervently in the background. The only time the DBWR wakes up is 1) when Oracle needs a free db_buffer and there isn’t available one. Then the DBWR will flush it – even if there are uncommitted txns OR 2) The LGWR isn’t able to do its job – the logfiles get wrapped around too fast and so it eventually forces a checkpoint so it could reuse redo group 1. The interim checkpoints during log switches funnily got ignored by Oracle in order to satisfy the load of the single massive update/delete (no matter what the log_checkpoint_interval is set to). So, CKPT is pretty lazy too. The only guy doing any work ‘under pressure’ is the LGWR.

Did I get it straight?

> so that measely 228 bytes of redo might be protecting 4 8k blocks (32k of data) that dbwr must flush out at some point

One other thing – how can I verify this? How can I verify that the DBWR wrote 4 blocks? With a trace and/or v$sysstat?

Many thanks for your time and patience.

dbwr is a piece of software that reacts according to the parameters set for it.


lgwr works in the background whilst you are filling up the redo log buffer and lgwr works "in the foreground" when you commit (you wait for lgwr)...

dbwr flushes blocks because we ran out of them (cache is full)

or lgwr signals a checkpoint on the log switch (not just when it switches all of the way around)

or because an incremental checkpoint was signaled (fast_start_mttr, log_checkpoint*)

and it does this every 3 seconds at least (makes the checks)

It is not that lgwr isn't able to do its job at all -- it is because lgwr did its job!



the interim checkpoints *did not get ignored*, they just did not complete.  big difference.

ops$tkyte@ORA9IR2> select * from v$sysstat where upper(name) like '%DBWR%';
 
STATISTIC# NAME                                CLASS      VALUE
---------- ------------------------------ ---------- ----------
        49 DBWR checkpoint buffers writte          8        155
           n
 
        50 DBWR transaction table writes           8         21
        51 DBWR undo block writes                  8         45
        52 DBWR revisited being-written b          8          0
           uffer
 
        53 DBWR make free requests                 8          0
        54 DBWR free buffers found                 8          0
        55 DBWR lru scans                          8          0
        56 DBWR summed scan depth                  8          0
        57 DBWR buffers scanned                    8          0
        58 DBWR checkpoints                        8          0
        59 DBWR cross instance writes             40          0
        60 DBWR fusion writes                     40          0
 
12 rows selected.

 

Thank you for the explanation.

> select * from v$sysstat where upper(name) like '%DBWR%';

Which statistic in the output tells me # of blocks written? I see # of checkpoint buffers written - but not # of blocks written to the datafiles. I guess it is the "physical writes" parameter that I should be looking at - correct?

well, physical writes is number of write calls -- and we could batch them up.  

checkpoint buffer is the number of block buffers that were written for checkpoints.

ops$tkyte@ORA9IR2> select * from v$sysstat where upper(name) like '%DBWR%';
 
STATISTIC# NAME                                CLASS      VALUE
---------- ------------------------------ ---------- ----------
        49 DBWR checkpoint buffers writte          8       1056
           n
 
        50 DBWR transaction table writes           8        275
        51 DBWR undo block writes                  8        586
        52 DBWR revisited being-written b          8          0
           uffer
 
        53 DBWR make free requests                 8         35
        54 DBWR free buffers found                 8      47717
        55 DBWR lru scans                          8         35
        56 DBWR summed scan depth                  8      47747
        57 DBWR buffers scanned                    8      47747
        58 DBWR checkpoints                        8          1
        59 DBWR cross instance writes             40          0
        60 DBWR fusion writes                     40          0
 
12 rows selected.
 
ops$tkyte@ORA9IR2> update big_table.big_table set object_name = object_name where rownum <= 10000;
 
10000 rows updated.
 
ops$tkyte@ORA9IR2> commit;
 
Commit complete.
 
ops$tkyte@ORA9IR2> alter system checkpoint;
 
System altered.
 
ops$tkyte@ORA9IR2>  select * from v$sysstat where upper(name) like '%DBWR%';
 
STATISTIC# NAME                                CLASS      VALUE
---------- ------------------------------ ---------- ----------
        49 DBWR checkpoint buffers writte          8       1885
           n
 
        50 DBWR transaction table writes           8        295
        51 DBWR undo block writes                  8        756
        52 DBWR revisited being-written b          8          0
           uffer
 
        53 DBWR make free requests                 8         35
        54 DBWR free buffers found                 8      47717
        55 DBWR lru scans                          8         35
        56 DBWR summed scan depth                  8      47747
        57 DBWR buffers scanned                    8      47747
        58 DBWR checkpoints                        8          2
        59 DBWR cross instance writes             40          0
        60 DBWR fusion writes                     40          0
 
12 rows selected.
 
 

is it possiable to send a alert to know when log switch happens?(possiable mail)... or trigger a shell.or at job...

thanks in advance .

Our database definitely has peaks and valleys. In particular, data is slowly entered into the DB, and then when a project is finished, the data gets "exported" into some archival format, and the entire project is then deleted from the DB in a single operation. This deletion, I would imagine, generates a pretty big redo spike. (After all, until the transaction commits, we might want to UNDO all that deletion...)

Anyway, I too am getting the message about no logs being free. (I can well believe it - I saw 41 log switches in less than 3 minutes in one case!)

I currently have 4 x 1MB redo logs. In your opinion, should I make the logs bigger, or just have more of them? (Or maybe I should do both?)

Oracle 8i - if it makes any difference.

Thanks - you rule BTW. ;-)

Right. Well, I've never had a database recovery session take longer than about... oh... 17 seconds. (Once you find the necessary file, if they have been moved.)

Anyway, thanks for your time Tom.

OK, well... the logs were too small. And now it seems I've made them too big. Heh!

Before I make any more changes to my DB, is there any way to figure out "how full" the current online redo log is? (I've looked at all the v$ views I can find, but none seems to tell me what I'm after...)

I'd just like it so that at least 1 log switch happen each day. (After all, only *archived* redo log gets onto tape...)

Yes, the logs are used in a circular fasion. Once the current log is filled up, Oracle starts filling the next one (while at the same time archiving the one it just filled). I'd like to know how close that is to happening - basically, to know how much redo we generate in a day. Currently, the only way I can figure out is to ask for a log switch, and see how big the archived log is.

As I say, I'd like one or more log switch per day. As I see it, I can make the logs smaller again, or I can schedule a job to run each day to ask Oracle to switch logs. (I assume it's possible to do such a thing.)

...alternatively, it might just be that they aren't using the DB much right now. Who knows? ;-) Anyway, would be nice to measure this thing...

Ooo... *lots* of statistics there... mmm. :-)

User commits = user rollbacks = 0... OOC, do these stats reset when you close the DB? Or are they permanently saved on disk?

Anyway, I assume it's the class 2 stuff I need to stare at...
("Blocks written" or something.)

BTW - thanks for the 9i tip. Can't wait to upgrade. LOL! (That is, assuming they don't decide to centralise the thing - that would be bad.)

 
ops$tkyte@ORA9IR2> select name, value from v$sysstat where name like '%redo%';
 
NAME                                VALUE
------------------------------ ----------
redo synch writes                       3
redo synch time                         0
redo entries                          492
redo size                          126044
redo buffer allocation retries          0
redo wastage                        11120
redo writer latching time               0
redo writes                            38
redo blocks written                   277
redo write time                         0
redo log space requests                 0
redo log space wait time                0
redo log switch interrupts              0
redo ordering marks                     0
 
14 rows selected.
 

redo size...  lots of redo stats. 

OK, well thanks for your help. I'm going to go away and do some testing now. But what I'm probably going to do is schedule a job to switch the logs periodically.

One last thing... do I have to use an "at" job to schedule this? Or does Oracle itself have some built-in facility to run a command periodically?

I'd just like to share on eof my past experinces. I was with a company that does processing related to credit cards. One of their databasa was very very actively used. Just to give an idea, they had E10K machine, 22 CPUs , 18GB memory and they were using EMC PowerPath for I/O balancing. The amount of redo generated was HUGE. When I joined there, this databse was having really very bad performance. By checking the ALERT logfile, found that they are doing checkpoint almost EVERY SECOND. their redolog file size was only 2MB. Increased the redo log file to 64MB and it was still doing the checkpoint almost every 30 seconds. and we were still getting checkpoint not complete messages in alert log. To make it short, in the end, what we did was we created a total of 12 redo log files each with 2GB of size. With that size, we were checkpoint after about 15 minutes.

Hi Tom

My db size is growing and approximately it would be around 5Tb.I am just wundering what should be the size of the datafiles .Should i restrict them to 2Gb each or we should allow them to grow 20Gb each..

My concern is if i have 2Gb datafile recovery would be easier isnt it

If i have 20Gb datafile checkpointing will be faster (i think )how much overhead does the checkpointing add anyway if we go for 2gb each file

we will be taking backups through flash snap from veritas.Which puts all the tablespaces in hotbackup mode and just breaks the mirrors.

how do i strike a balance ?

My linux os does not have problems with 2gb file systems.

How do find the blocksize for ext3 file systems on linux like its 8kb 4kb etc ?

To : hrishy

I had 5 TB database and I'm using some datafiles with 64GB sizes ....

In 10g, they have BIGfile tablespace ... you'll working just on tablespaces, not on datafiles anymore ...like
ALTER TABLESPACE bigts RESIZE <whatever> ;

SELECT
le.leseq CURRENT_LOG_SEQUENCE#,
100*cp.cpodr_bno/LE.lesiz PERCENTAGE_FULL
from
x$kcccp cp,x$kccle le
WHERE
LE.leseq =CP.cpodr_seq
/

The above script will tell you how of your current redo log file is full.. i dont know whether it will fulfill your purpose..

I talked to one of Oracle analyist through Metalink,
he said this could bring the database down eventually, is this true ? If not what is the worse case of scenario could happened ? Is this could cause the whole database hanging even for query or not allowed any dml any more?

Sorry , I didn't make it clear. What I mean is the message "checkpoint no complete, can not add new logs".
Since it won't give you any ORA- error and the analyst from Oracle said it could bring the instance down without warnings, that why I what to ask if this is true. And how to be precautious .

Thanks very much

Can I assume safely that the log switch check point ensures that the archive log copy process is successfully over??

Tom, have you heard some side effect as ORA-12519 by having "cannot allocate new log, sequence ..." contention before?
It's about a java application under Tomcat.

alert is pointing "cannot allocate new log, ..."
Before increasing redolog, I'd like to know if it's related each other.

Regards,
Marcio Portes.

What is the use of ALERT LOG FILES for DBA(checkpoint information is needed for DBA or anything else also)

what is the important information DBA will get from ALERT LOG FI

Dear Tom
Suddendly after increasing the number of dbwr from 4 to 6(which we did after free buffer waits were encountered as top event in the staspack and the application was hanging) now that "Checkpoint not complete" have started appearing in the log files too frequently since last few days.Could you explain why by increasing the dbwr that message should start appearing all of a sudden?

I checked with my system admin for any io contention, he says it looks alright to him.In the meantime that particular wait "Checkpoint not complete" has vanished from the statspack report as well eventhough we have not done any specific change at all.
Also while that wait event came in we did not do less transactions as suggested we were still doing 310 transactions/sec.So after increasing the dbwr from 4 to 6 that wait popped up for 4 days and now since couple of days theres no sign of it.Could you shed some light on this as your comments are invaluable.
Thanks.

Checked with the app team they say they dint run any reports nor there was any module added.In short there was no burst at that time and my concern is that it wasnt for a hour or so it came continuosly for 4 days then disappeared again.
My logs are sized at 500MB with 8 groups and log_bugger=10M.
Now since that event has gone and application is running fine do you still think that increasing the size or groups will help or should i leave it as it is?
If i do increase the size of redo logs is there any direct corealation between log_buffer and redo log size.
Thanks

Thanks Tom
And what about my second query as regarding the increasing log buffer and log size?

Hi Tom,

The alert log contents are following:

Fri Apr 7 00:44:09 2006
Thread 1 cannot allocate new log, sequence 1114
Checkpoint not complete
Current log# 2 seq# 1113 mem# 0: /redo-02-a/databases/admw/redo-t01-g02-m1.log
Current log# 2 seq# 1113 mem# 1: /redo-04-a/databases/admw/redo-t01-g02-m2.log
Private_strands 121 at log switch
Beginning log switch checkpoint up to RBA [0x45a.2.10], SCN: 0x0000.7040ac15
Thread 1 advanced to log sequence 1114
Current log# 4 seq# 1114 mem# 0: /redo-02-a/datab Current log# 4 seq# 1114 mem# 1: /redo-04-a/databases/admw/redo-t01-g04-m2.log
Fri Apr 7 00:44:12 2006
ARC2: Evaluating archive thread 1 sequence 1113
ARC2: Destination LOG_ARCHIVE_DEST_2 archival not expedited
Fri Apr 7 00:44:12 2006
ARC2: Beginning to archive thread 1 sequence 1113 (1883282802-1883286549) (admw)
ARCH: Connecting to console port...
Fri Apr 7 00:44:12 2006
ARC2: Creating local archive destination LOG_ARCHIVE_DEST_1: '/arch-01/databases/admw/redolog-1113-1-583227512.arc' (thread 1 sequence 1113)
(admw)
ARCH: Connecting to console port...
Fri Apr 7 00:44:12 2006
ARC2: Closing local archive destination LOG_ARCHIVE_DEST_1: '/arch-01/databases/admw/redolog-1113-1-583227512.arc'
(admw)
ARCH: Connecting to console port...
Committing creation of archivelog '/arch-01/databases/admw/redolog-1113-1-583227512.arc'
Invoking non-expedited destination LOG_ARCHIVE_DEST_2 thread 1 sequence 1113 host admw_b
Fri Apr 7 00:44:12 2006
ARC2: Completed archiving thread 1 sequence 111ARCH: Connecting to console port...
FAL[server, ARC2]: Begin FAL noexpedite archive (branch 583227512 thread 1 sequence 1113 dest admw_b)
Fri Apr 7 00:44:12 2006
ARC2: Creating remote archive destination LOG_ARCHIVE_DEST_2: 'admw_b' (thread 1 sequence 1113)
(admw)
ARCH: Connecting to console port...
ARC2: Standby redo logfile selected for thread 1 sequence 1113 for destination LOG_ARCHIVE_DEST_2
Fri Apr 7 00:44:12 2006
ARC2: Closing remote archive destination LOG_ARCHIVE_DEST_2: 'admw_b'
(admw)
ARCH: Connecting to console port...
FAL[server, ARC2]: Complete FAL noexpedite archive (thread 1 sequence 1113 destination admw_b)
Fri Apr 7 00:49:14 2006
Completed checkpoint up to RBA [0x45a.2.10], SCN: 1883286549
Fri Apr 7 00:53:29 2006
Incremental checkpoint up to RBA [0x45a.7a1.0], current log tail at RBA [0x45a.ec1.0]
Fri Apr 7 01:04:25 2006
Fri Apr 7 01:14:09 2006
Thread 1 cannot allocate new log, sequence 1115
Checkpoint not complete
Current log# 4 seq# 1114 mem# 0: /redo-02-a/databases/admw/redo-t01-g04-m1.log
Current log# 4 seq# 1114 mem# 1: /redo-04-a/databases/admw/redo-t01-g04-m2.log
Private_strands 121 at log switch
Beginning log switch checkpoint up to RBA [0x45b.2.10], SCN: 0x0000.70414f38
Thread 1 advanced to log sequence 1115
Current log# 3 seq# 1115 mem# 0: /redo-01-a/databases/admw/redo-t01-g03-m1.log
Current log# 3 seq# 1115 mem# 1: /redo-03-a/databases/admw/redo-t01-g03-m2.log
Fri Apr 7 01:14:12 2006
ARC2: Evaluating archive thread 1 sequence 1114
ARC2: Destination LOG_ARCHIVE_DEST_2 archival not expedited
Fri Apr 7 01:14:12 2006
ARC2: Beginning to archive thread 1 sequence 1114 (1883286549-1883328312) (admw)
ARCH: Connecting to console port...
Fri Apr 7 01:14:12 2006
ARC2: Cre (admw)
ARCH: Connecting to console port...
Fri Apr 7 01:14:14 2006
ARC2: Closing local archive destination LOG_ARCHIVE_DEST_1: '/arch-01/databases/admw/redolog-1114-1-583227512.arc'
(admw)
ARCH: Connecting to console port...
Committing creation of archivelog '/arch-01/databases/admw/redolog-1114-1-583227512.arc'
Invoking non-expedited destination LOG_ARCHIVE_DEST_2 thread 1 sequence 1114 host admw_b
Fri Apr 7 01:14:14 2006
ARC2: Completed archiving thread 1 sequence 1114 (1883286549-1883328312) (admw)
ARCH: Connecting to console port...
FAL[server, ARC2]: Begin FAL noexpedite archive (branch 583227512 thread 1 sequence 1114 dest admw_b)
Fri Apr 7 01:14:14 2006
ARC2: Creating remote archive destination LOG_ARCHIVE_DEST_2: 'admw_b' (thread 1 sequence 1114)
(admw)
ARCH: Connecting to console port...
ARC2: Standby redo logfile selected for thread 1 sequence 1114 for destination LOG_ARCHIVE_DEST_2
Fri Apr 7 01:14:17 2006
ARC2: Closing remote archive destination LOG_ARCHIVE_DEST_2: 'a (admw)
ARCH: Connecting to console port...
FAL[server, ARC2]: Complete FAL noexpedite archive (thread 1 sequence 1114 destination admw_b)
Fri Apr 7 01:19:12 2006
Completed checkpoint up to RBA [0x45b.2.10], SCN: 1883328312
Fri Apr 7 01:23:29 2006
Incremental checkpoint up to RBA [0x45b.1e8.0], current log tail at RBA [0x45b.1237.0]
Fri Apr 7 01:44:09 2006
Thread 1 cannot allocate new log, sequence 1116
Checkpoint not complete
Current log# 3 seq# 1115 mem# 0: /redo-01-a/databases/admw/redo-t01-g03-m1.log
Current log# 3 seq# 1115 mem# 1: /redo-03-a/databases/admw/redo-t01-g03-m2.log
Private_strands 121 at log switch
Beginning log switch checkpoint up to RBA [0x45c.2.10], SCN: 0x0000.70415e20
Thread 1 advanced to log sequence 1116
Current log# 1 seq# 1116 mem# 0: /redo-01-a/databases/admw/redo-t01-g01-m1.log
Current log# 1 seq# 1116 mem# 1: /redo-03-a/databases/admw/redo-t01-g01-m2.log
Fri Apr 7 01:44:12 2006
ARC2: Evaluating archive thread 1 sequence 1115
ARC2: Destination LFri Apr 7 01:44:12 2006
ARC2: Beginning to archive thread 1 sequence 1115 (1883328312-1883332128) (admw)
ARCH: Connecting to console port...
Fri Apr 7 01:44:12 2006
ARC2: Creating local archive destination LOG_ARCHIVE_DEST_1: '/arch-01/databases/admw/redolog-1115-1-583227512.arc' (thread 1 sequence 1115)
(admw)
ARCH: Connecting to console port...
Fri Apr 7 01:44:12 2006
ARC2: Closing local archive destination LOG_ARCHIVE_DEST_1: '/arch-01/databases/admw/redolog-1115-1-583227512.arc'
(admw)
ARCH: Connecting to console port...
Committing creation of archivelog '/arch-01/databases/admw/redolog-1115-1-583227512.arc'
Invoking non-expedited destination LOG_ARCHIVE_DEST_2 thread 1 sequence 1115 host admw_b
Fri Apr 7 01:44:12 2006
ARC2: Completed archiving thread 1 sequence 1115 (1883328312-1883332128) (admw)
ARCH: Connecting to console port...
FAL[server, ARC2]: Begin FAL noexpedite archive (branch 583227512 thread 1 sequence 1115 dest admw_b)
Fri Apr 7 01:44:12 2006
ARC2: Creating rem (admw)
ARCH: Connecting to console port...
ARC2: Standby redo logfile selected for thread 1 sequence 1115 for destination LOG_ARCHIVE_DEST_2
Fri Apr 7 01:44:13 2006
ARC2: Closing remote archive destination LOG_ARCHIVE_DEST_2: 'admw_b'
(admw)
ARCH: Connecting to console port...
FAL[server, ARC2]: Complete FAL noexpedite archive (thread 1 sequence 1115 destination admw_b)
Fri Apr 7 01:49:14 2006
Completed checkpoint up to RBA [0x45c.2.10], SCN: 1883332128
Fri Apr 7 01:53:29 2006
Incremental checkpoint up to RBA [0x45c.28a.0], current log tail at RBA [0x45c.c48.0]
Fri Apr 7 02:14:07 2006
Thread 1 cannot allocate new log, sequence 1117
Checkpoint not complete

Even after setting the few parameters of the init.ora as, still getting the error message :

sys@ADMW>show parameter db_writer

NAME TYPE VALUE
------------------------------------ ----------- ----------db_writer_processes integer 4

sys@ADMW>show parameter fast_start_mttr
NAME TYPE VALUE
------------------------------------ ----------- ----------fast_start_mttr_target integer 120

The V$log is also displayed :
sys@ADMW>/

GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- -----------
1 1 1132 536870912 2 YES INACTIVE 1883674146 07-APR-2006
2 1 1133 536870912 2 YES INACTIVE 1883708203 07-APR-2006
3 1 1135 536870912 2 NO CURRENT 1883780045 07-APR-2006
4 1 1134 536870912 2 YES INACTIVE 1883746995 07-APR-2006

What else can be done to get rid of the error. The redo logs are on independent disks and the ARCH is reading them from these filesystems and creating them on a totally different file system on different controllers and disks.

Please advice, what to do to solve this error. Do I need to add more groups, so that DBWR gets sufficient time to flush the dirty buffers from the queue which have already been logged when LGWR attempts to reuse the file.

Your advice will be appreciated.

Thanks

Tom,
You are advising to add new logfile to minimize 'Checkpoint not comple' error. I don't understand this. If check checkpoint occurs at every logswitch, the if you have 3 logfiles or 1000, how it is going to help? Database will not switch to next logfile unless check point is not complete. So in my opinion increasing checkpoint frequency or increasing logfile size are the only two options to handle 'checkpoint not complete' error. Please correct me if I am wrong?

Thanks for your response.

Is there any drawback of having many online redo log files. I have currently 14 logfiles, why not 100 ?

Hi tom,

Based on your suggestion added 4 more log groups of SIZE 512M, to already existing 4 redo log groups but still the message in the alert log doesn't goes off.

sys@ADMW>/

GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- -----------
1 1 1332 536870912 2 YES INACTIVE 1888231924 11-APR-2006
2 1 1333 536870912 2 YES INACTIVE 1888251634 11-APR-2006
3 1 1331 536870912 2 YES INACTIVE 1888202124 11-APR-2006
4 1 1334 536870912 2 NO CURRENT 1888283242 11-APR-2006
5 1 1327 536870912 2 YES INACTIVE 1888127096 11-APR-2006
6 1 1328 536870912 2 YES INACTIVE 1888159889 11-APR-2006
7 1 1329 536870912 2 YES INACTIVE 1888164314 11-APR-2006
8 1 1330 536870912 2 YES INACTIVE 1888197375 11-APR-2006

What is your recommendation, should I continue to add more redo log groups.

Is there a way to see how many more redo log groups do we require to get rid of the message.

Thanks

Hi Tom,

This is the normal processing this database undertakes, every hour the data is getting loaded in the tables especially 2 hot spot tables worth 7 million records.

Please suggest, the next course of action. I have even alterted the FAST_START_MTTR_TARGET , low to 60 secs but still no effect.

Thanks

We have redolog of 100m and getting checkpoint no completed error. Do you think we should increase size from 100 to 500M?

Oracle Version: 9.2.0.5
Operating System: Solaris 8
setup: 4 redo log files, each one sized at 200M.

I just want to make sure I understood this correctly. We get
a lot of the following errors:

Thread <x> cannot allocate new log, sequence 104316
All online logs needed archiving

But we only had one:

Thread 1 cannot allocate new log, sequence 104300
Checkpoint not complete

Would it be correct to assume that DBWR is not the main
problem. The problem may be more the speed at which the
redo log files are written to the archive destination? Or
am I out in left field on this.

In either case though, I guess the easiest solution is
to add more redo files?

Thanks

Steve

Thanks Tom!

So there's nothing we can do to speed up ARCH (other than
faster disks I guess) - correct?

More redo log files should do the trick - correct?

We are seeing checkpoint not complete messages, and I appreciate your comments about DBWR not keeping up. I think I see some correlation between the problems and jobs which update the same records multiple times over a long period in the same unit of work. Could this be a cause? In general, how does Oracle handle the flushing out of data blocks which have been dirtied bewteen the start of the checkpoint and DBWR pushing them out to disk? Might the checkpoint complete message get delayed because the block got dirty again?

Tom,
I read your book Expert Oracle Database Architecture. Well, at least the part explaining 'Checkpoint not complete' error. I also read your very first answer on this page to a 'Checkpoint not complete' issue that William was having. I am confused after reading both the answers.

I have bolded the questions that I need answers for below.

The second square bullet on page 177 in your book says:
"Recreate the log files with a larger size. This will extend the amount of time between the time we fill the online redo log, and the time we need to reuse it."

One of the answers on this page says:
"Another way is to make the log files smaller, hence increasing the frequency with which we checkpoint"

These points seem to contradict each other. Can you qualify the points? In which case would you increase the log file size and in which case would you make it small?

We are getting "Checkpoint not complete" message in one of our databases. There are 4 redo log groups with single member in them - each sized to 200MB. Is it too big size? I would also like to say that it is not related to a slow ARCH process since I don't see "Archival required" message in the alert log.
DB_WRITER_PROCESSES is set to 2. FAST_START_MTTR_TARGET is set to 0. I don't care about recovery time right now. On page 94 of your book you say to increase DB_BLOCK_LRU_LATCHES parameter when I increase DB_WRITER_PROCESSES. This parameter is obsolete in 10.1.0.4. Then what's the equivalent parameter in 10.1.0.4? Our database is on RHEL4U3, Oracle 10.1.0.4.

DISK_ASYNC_IO is set to TRUE. The "Checkpoint not complete" message has occurred 3 times in the last 4 days since I have made the redo log file size 200MB and set up 4 redo log files. I am not sure what I should do now.

On a general note, I don't understand the logic behind making redo log file size smaller. The solution to get rid of this error is to spread out checkpoints as farther as possible. Making redo log file size small would cause more frequent log switches, in turn more frequent checkpoints - increasing the likelihood of this issue. What am I not understanding here?

You have also mentioned in the book about postponing the message. Is our aim only to postpone it? Is this message inevitable then?

Can you help?

I understand both the points. I guess the answer is 'depends'. ;-)

About the recovery, when I said I don't care about the recovery, I meant just NOW. I would rather get rid of these abrupt pauses in the database operation than to worry about the recovery time. Besides, FAST_START_MTTR_TARGET is set to 0 by default. I haven't changed it so it shouldn't affect my checkpointing. Correct?

But back to my main question, what do you think I should do? Why should I be getting this message with 200MB redo log file?

Thank you,
Prashant

How do I find out the history of when the checkpoints occur? Any v$ table that will tell me at what time an incremental or full checkpoint is occurring?

What am I missing here?

I have 5 redo log files each 200MB. I set FAST_START_MTTR_TARGET to 120 seconds. I am still getting "Checkpoint not complete" message at the bottom.

Tue Feb 27 16:41:38 2007
ALTER SYSTEM SET fast_start_mttr_target=120 SCOPE=BOTH;
Tue Feb 27 16:42:18 2007
Completed checkpoint up to RBA [0x32d6.2.10], SCN: 619134734
Tue Feb 27 16:51:21 2007
Incremental checkpoint up to RBA [0x32d6.13777.0], current log tail at RBA [0x32d6.21ec5.0]
Tue Feb 27 17:07:13 2007
Private_strands 48 at log switch
Beginning log switch checkpoint up to RBA [0x32d7.2.10], SCN: 0x0000.24e9eecf
Thread 1 advanced to log sequence 13015
  Current log# 2 seq# 13015 mem# 0: /u03/flash_recovery_area/UP10G/onlinelog/o1_mf_2_2y1bz3fn_.log
Tue Feb 27 17:07:13 2007
ARC1: Evaluating archive thread 1 sequence 13014
Tue Feb 27 17:07:13 2007
ARC1: Beginning to archive thread 1 sequence 13014 (619134734-619310799) (up10g)
ARCH: Connecting to console port...
Tue Feb 27 17:07:13 2007
ARC1: Creating local archive destination LOG_ARCHIVE_DEST_10: '/u03/flash_recovery_area/UP10G/archive
log/2007_02_27/o1_mf_1_13014_%u_.arc' (thread 1 sequence 13014)
 (up10g)
ARCH: Connecting to console port...
Tue Feb 27 17:07:23 2007
ARC1: Closing local archive destination LOG_ARCHIVE_DEST_10: '/u03/flash_recovery_area/UP10G/archivel
og/2007_02_27/o1_mf_1_13014_2y9bwkx0_.arc'
 (up10g)
Tue Feb 27 17:07:24 2007
ARCH: Connecting to console port...
Committing creation of archivelog '/u03/flash_recovery_area/UP10G/archivelog/2007_02_27/o1_mf_1_13014
_2y9bwkx0_.arc'
Created Oracle managed file /u03/flash_recovery_area/UP10G/archivelog/2007_02_27/o1_mf_1_13014_2y9bwk
x0_.arc
Tue Feb 27 17:07:25 2007
ARC1: Completed archiving thread 1 sequence 13014 (619134734-619310799) (up10g)
ARCH: Connecting to console port...
Tue Feb 27 17:08:40 2007
Thread 1 cannot allocate new log, sequence 13016
Checkpoint not complete
  Current log# 2 seq# 13015 mem# 0: /u03/flash_recovery_area/UP10G/onlinelog/o1_mf_2_2y1bz3fn_.log

What can I do?

Log switching is happening every 20 to 30 minutes.

/u03/flash_recovery_area filesystem does have some contention.
My online redo logs, archive logs and backup image copies are on this filesystem.
How do I find out how much contention though?

Hi Tom,
We have redolog of 40 group 25m and still getting checkpoint no completed error. what should we do now?

Hi Tom,

First of all, thank you for all you explain us since so long.

I am working on a DB which gives ""checkpoint not complete, cannot allocate new log" alerts, but I don't understand what an Oracle doc explains.
Especially the "90%" point and the priority between checkpoints and actual work they do each.

Can You please help me ?

Thank you, best regards,

Christophe.

Metalink note 76713.1
(...)
"So, when Oracle does a checkpoint due to a log switch, it does not really have to do anything. The checkpoint position is already advanced out of the soon to be reused log. The log switch checkpoint does not actually do
anything right away. It is a "zero priority" checkpoint: it does not cause any writes to happen on its own, but is marked as complete only when checkpointing for other reasons causes the checkpoint position to advance
beyond the rba that marked the end of the log when the checkpoint was initiated.

Example:
--------

Assume you have two logs, A and B. When B fills, Oracle initiates a zero priority checkpoint to advance the checkpoint position to the end of log B.
However, because the checkpoint position is no more than 90% of the size of the smallest log behind the end of the log, the checkpoint position is roughly
10% of the way into log B when this checkpoint is initiated. There is no reason to do any writes, as log A can be reused immediately. So Oracle does nothing and lets the checkpoint position continue to advance based upon other factors. When the other factors cause the checkpoint position to advance beyond the end of log B, the zero priority checkpoint previously initiated is
declared complete and you see the checkpoint complete message.

Note: If you manually switch log files, the checkpoint position may not have advanced out of the log to be reused. In this case, Oracle initiates a real checkpoint and advances the checkpoint position up to the rba that marked the end of the log when the checkpoint
was initiated."

Hi,

if you are on 10GR2 you can use the following view to set the optimal values for fast_start_mttr_target and log file size.

select ir.optimal_logfile_size,
ir.log_file_size_redo_blks,
ir.estimated_mttr,
ir.target_mttr
from v$instance_recovery ir

start with fast_start_mttr_target=v$instance_recovery.estimated_mttr
and then keep watching the value of v$instance_recovery.optimal_logfile_size

Regards,

Pasko

Hello Tom,
Is that the right way to set the optimal value ?

<<START>>
select ir.optimal_logfile_size,
ir.log_file_size_redo_blks,
ir.estimated_mttr,
ir.target_mttr
from v$instance_recovery ir

start with fast_start_mttr_target=v$instance_recovery.estimated_mttr
and then keep watching the value of v$instance_recovery.optimal_logfile_size

<<END>>

In our case the value of fast_start_mttr_target = 60 and the v$instance_recovery.estimated_mttr = 23.

Hi Tom,

Great explanation for the alert log messages..
But something that baffles me is that after I had received the Checkpoint meesages in my alert log .. there are no further ARC0 messages similar to the following

ARC0: Evaluating archive log 12 thread 1 sequence 2595
ARC0: Beginning to archive log 12 thread 1 sequence 2595
Creating archive destination LOG_ARCHIVE_DEST_1: '/oracle/XXX/oraarch/XXXarch1_2595.dbf'
ARC0: Completed archiving log 12 thread 1 sequence 2595
Wed Jan 10 07:30:03 2007


When I got the Checkpoint error , the redolog were defined as such

4 online redolog groups with 2 members each and 50 MB each

Then I resized the redologs to 100MB.

The log buffer is 2 MB.

I still get the Checkpoint message.. and in addition to that there are no ARC0 messages though the archives are generated successfully.

The messages received during the checkpoint error are the following

************
Thread 1 advanced to log sequence 14288
Current log# 4 seq# 14288 mem# 0: /oracle/XXX/origlogB/log_g4m1.dbf
Current log# 4 seq# 14288 mem# 1: /oracle/XXX/mirrlogB/log_g4m2.dbf
Wed Jan 14 12:29:23 2009
Thread 1 cannot allocate new log, sequence 14289
Checkpoint not complete
Current log# 4 seq# 14288 mem# 0: /oracle/XXX/origlogB/log_g4m1.dbf
Current log# 4 seq# 14288 mem# 1: /oracle/XXX/mirrlogB/log_g4m2.dbf
Wed Jan 14 12:29:26 2009
Completed checkpoint up to RBA [0x37ce.2.10], SCN: 839619203
Wed Jan 14 12:29:30 2009
Beginning log switch checkpoint up to RBA [0x37d1.2.10], SCN: 839620666
Thread 1 advanced to log sequence 14289
Current log# 1 seq# 14289 mem# 0: /oracle/XXX/origlogA/log_g1m1.dbf
Current log# 1 seq# 14289 mem# 1: /oracle/XXX/mirrlogA/log_g1m2.dbf
Wed Jan 14 12:30:01 2009
Thread 1 cannot allocate new log, sequence 14290
Checkpoint not complete
Current log# 1 seq# 14289 mem# 0: /oracle/XXX/origlogA/log_g1m1.dbf
Current log# 1 seq# 14289 mem# 1: /oracle/XXX/mirrlogA/log_g1m2.dbf
Wed Jan 14 12:30:04 2009
Completed checkpoint up to RBA [0x37cf.2.10], SCN: 839620446
Wed Jan 14 12:30:06 2009
Beginning log switch checkpoint up to RBA [0x37d2.2.10], SCN: 839620958

**********************

Any advice would be much appreciated.

Meanwhile I am also getting the below messages in trace files XXX_arc0_22279.trc and XXX_arc1_22281.trc

*** 2009-01-15 11:34:23.950
kcrrwkx: nothing to do (end)
*** 2009-01-15 11:35:23.951
kcrrwkx: nothing to do (end)
*** 2009-01-15 11:36:23.951
kcrrwkx: nothing to do (end)


Metalink suggests this is a bug . But would this error suppress the ARC0 meesages in the alert log?

THanks in advance ,

Sandeep Kurian

Dear Tom,

the infamous "checkpoint not complete, cannot allocate new log" message.

this occurrs when Oracle attempts to reuse a log file but the checkpoint that would flush
the blocks that may have redo in this log file has not yet completed -- we must wait
until that checkpoint completes before we can reuse that file -- thats when this message
is printed. during this time (when we cannot allocate a new log) processing is suspended
in the database while the checkpoint is made to complete ASAP.

In the above explanation System will suspend till checkpoint completes. I have a doubt there.

This will happen only when oracle try to overwrite the log file to restart the log cycle and again if there is commited data in the log file which is going to be over written. Other wise system function will continue with out suspending
AM i correct please explain

We are also getting this error on our 11G database:

Thread 1 cannot allocate new log, sequence 1858
Private strand flush not complete

Oracle Metalink note 372557.1 says that a "strand" is a new 10gr2 term for redo latches and is not an error?

But it has lead to a database crash on our system:

Thread 1 cannot allocate new log, sequence 1851
Checkpoint not complete
Current log# 2 seq# 1850 mem# 0: M:\ORACLE\REDOB\BUKSPROD\REDO02B.LOG
Current log# 2 seq# 1850 mem# 1: N:\ORACLE\REDOA\BUKSPROD\REDO02A.LOG
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 2264'

The system crashed.

We have our current redo log set to 50Mbytes and find that they switch 1 to 2 times per hour during the day and 4 to 5 times during backups and exports ( the previous error happended during an export). We have our parameters set as so:

log_checkpoint_interval integer 0
log_checkpoint_timeout integer 0
fast_start_io_target integer 0
fast_start_mttr_target integer 360

When we query the v$instance_recovery view we get very large values for the OPTIMAL_LOGFILE_SIZE (e.g. 6836) That's in megabytes!

In order to prevent the 'cannot allocate' maybe we should be looking at changing the fast_start_mttr_target or even switching it off in favour of the log_checkpoint parameters?

Tom,

1. Will DBWR flash dirty buffers triggered by log switch or continuous checkpoint if one transaction updates blocks and another continually re-reads the same data effectively pinning those blocks in buffers at MRU end of LRU?

2. Is checkpoint information actually written to redo logs and if so does it happen right after DBWR finished?

hi tom
i read 435887.1 in metalink.
it said can use this method to simulate the isuus "log can't allocate';


SQL> alter system switch logfile; 
System altered. 

Alert log shows the following. 

Thread 1 advanced to log sequence 206 
Current log# 3 seq# 206 mem# 0: +GROUP01/oasm/onlinelog/group_3.258.609176403 
Current log# 3 seq# 206 mem# 1: +GROUP01/oasm/onlinelog/group_3.263.609176613 

Now connect to another session (using scott/tiger schema object in the example) and leave an update TX active. 

SQL> update emp set sal = sal * 1; 
14 rows updated. 
... do not commit and keep session active 
---in my opinion, this step only modify the db block in db cache,lgwr did't wirte the modify log into redo log,is it right?

Then manually switch the logs in the original session, and now the alert log shows the following messages. 


Or the following.

Thread 1 cannot allocate new log, sequence 85 
Private strand flush not complete 
Current log# 3 seq# 84 mem# 0: C:\ORACLE\ORA11\ORADATA\ORCL11\REDO03.LOG 
--this happen i guess ,  because  we did't commit the update,so lgwr did't write the update log to redo log,
is that right?

so my question is when i did't commit a transcation,
will lgwr write the redo to redo log, and if it write,
how can you explain  the above simulate issue happen? 

Tom;

I am in Chapter 3 in your Expert Oracle Database architecture book;
I have some issues during reading redolog files topic.

Suppose
I issue insert:
It is in buffer cache now, and it is in redolog buffer.(not yet written to redolog files)

1-)What if system crushes immediately before lgwr writes the data to redolog files? Is the data lost?

2-)Assume the lgwr writes the data to redologs, and system crashes before checkpoint.
Does oracle get the transaction from redolog and reexecute it.( so that it will again be buffer cache,and waiting for checkpoint)
or
put the data directly into datafiles bypass buffer cache?

3-) When I perform simple insert or update :
Does Oracle write the new row to buffercache and after checkpoint this data is written to disk (datafiles).
or
At First, Oracle retrieves the empty block from disk and put it into buffer cache and then perform insert into buffer cache, and again after checkpoint this will be written to disks

Hi Tom,
is there a way to measure the duration of the database freeze while waiting for checkpoint to complete?

I would of course prefer "a database way" to "an operating system way" :)

Thanks in advance,
Loïc

Thanks Tom to point ASH.

Could you maybe advise for the following query:

WITH my_data AS (SELECT sample_id, 
                        cast(sample_time AS DATE) AS sample_time, 
                        MAX(time_waited) / 1000000 AS time_waited_s, 
                        min(event) AS event 
                   FROM v$active_session_history 
                  WHERE event like '%log file switch%'
                    AND session_state='WAITING'
               GROUP BY sample_id, sample_time),
my_data2 AS (SELECT row_number() over (ORDER BY sample_id) r, 
                    sample_id, 
                    sample_time, 
                    decode(sample_id - lag(sample_id) over (ORDER BY sample_id),1,1,NULL) AS diff, 
                    time_waited_s, 
                    event
               FROM my_data)
SELECT d.sample_time, 
       d.event, 
       (SELECT SUM(time_waited_s) FROM my_data2 d2 WHERE d2.r BETWEEN d.r AND d.r2) AS time_waited_s
  FROM (SELECT d.*, 
               nvl((SELECT MIN(d2.r)-1 FROM my_data2 d2 WHERE d2.r > d.r AND d2.diff IS NULL),
                   (SELECT MAX(d2.r) FROM my_data2 d2))AS r2 
          FROM my_data2 d
       ) d 
 WHERE diff IS NULL;

Which aims to say when a freeze occured and of course the duration of the freeze:

SAMPLE_TIME EVENT                                              TIME_WAITED_S
----------- -------------------------------------------------- -------------
07/08/2009  log file switch completion                             10.372336
07/08/2009  log file switch completion                              5.975531
07/08/2009  log file switch (private strand flush incomplete)       0.403701
07/08/2009  log file switch completion                              1.864275
07/08/2009  log file switch completion                              0.043123
07/08/2009  log file switch (private strand flush incomplete)       2.619294
07/08/2009  log file switch (private strand flush incomplete)       0.549646
07/08/2009  log file switch (private strand flush incomplete)       0.940027
07/08/2009  log file switch completion                              6.762621
07/08/2009  log file switch completion                               6.83921
07/08/2009  log file switch (checkpoint incomplete)                 1.609012
07/08/2009  log file switch (checkpoint incomplete)                 2.531256
07/08/2009  log file switch completion                              0.643473
07/08/2009  log file switch (checkpoint incomplete)                 1.954845
07/08/2009  log file switch (checkpoint incomplete)                 0.103907
07/08/2009  log file switch completion                               0.97085
07/08/2009  log file switch (private strand flush incomplete)       0.976165
07/08/2009  log file switch completion                              0.167953
07/08/2009  log file switch (checkpoint incomplete)                 1.856985
07/08/2009  log file switch completion                              0.734215
07/08/2009  log file switch (checkpoint incomplete)                 3.642008
07/08/2009  log file switch (checkpoint incomplete)                 3.733871
07/08/2009  log file switch (private strand flush incomplete)       2.666382
07/08/2009  log file switch (private strand flush incomplete)       0.824016
07/08/2009  log file switch (private strand flush incomplete)       0.343181
07/08/2009  log file switch completion                              0.015503
07/08/2009  log file switch (private strand flush incomplete)       0.536985
07/08/2009  log file switch completion                              0.976511
07/08/2009  log file switch (private strand flush incomplete)       0.978144
07/08/2009  log file switch completion                              0.060924

Thanks in advance,
Loïc

Of course a

...
SELECT to_char(d.sample_time,'DD/MM/YYYY HH24:MI:SS') AS sample_time, 
       d.event, 
       round((SELECT SUM(time_waited_s) FROM my_data2 d2 WHERE d2.r BETWEEN d.r AND d.r2),1) AS time_waited_s
...

to format would be better.

Loïc

Today I was going through an OTN discussion on "When log_buffer flush?".
http://forums.oracle.com/forums/thread.jspa?threadID=940809

The discussion has used a new terminology(new for me) "Private Redo", which I think is introduced in 10g as above mentioned metalink note states.
I request you to please explain the terminology "Private Redo" and "strand".

Thanks,
Santosh

Thanks Tom,

Your simple words are more elaborative and make things look easy.
Will you please clear one more thing, what do you mean by "relatively small". Can we quantify this? Is similar sort of structure present for undo also?

Regards,
Santosh Kumar

hi tom
the redolog files & lgwr activites explained by you are really greate
however i would like you to answer the same with respect to a dataguard configuration
i get messages as
ARC7: Evaluating archive log 9 thread 1 sequence 422493
ARC7: Destination LOG_ARCHIVE_DEST_3 archival not expedited
ARC7: Destination LOG_ARCHIVE_DEST_2 archival not expedited
ARC7: Beginning to archive log 9 thread 1 sequence 422493
Creating archive destination LOG_ARCHIVE_DEST_1: '/archival/ONLINEPD/arch/ONLINEPD_1_422493.arc'
Invoking non-expedited destination LOG_ARCHIVE_DEST_2 thread 1 sequence 422493 host ONLINEPD_DR
Invoking non-expedited destination LOG_ARCHIVE_DEST_3 thread 1 sequence 422493 host ONLINEPD_FALL
ARC7: Completed archiving log 9 thread 1 sequence 422493
ARC7: Begin FAL noexpedite archive (thread 1 sequence 422456 destination ONLINEPD_FALL)


in my prod alert ,so what should i get
i am really confused

Hi sir;
Just for the experiement:
I shutdown the database and restore old redologs and create a controlfile with noresetlogs option
It fails with:
ORA-01229: data file 4 is inconsistent with logs.

How can oracle understand if the current online redologs are consistent or not?
Is there a data dictionary view that I can check wheter redologs are consistent or not?

For the controlfiles and datafiles, I can compare the checkpointScn in v$datafile and v$datafile_header.
However I have no idea how to compare redologs?

Thanks sir.
Can I see this information in v$datafile_header view? or any other view?

there is a very nice troubleshooting guide on metalink
"Checkpoint Tuning and Troubleshooting Guide [ID 147468.1]"

plz don't make fun of me thnks

Hi Tom

i just recently upgraded from 10.2.0.4 to 10.2.0.5 on a test server and was running some checks
In creating some test tables using a select statement such as

create table <tablename> as select * from <tablename>;

Note: the table has a total 5377922 records


I noticed that i was getting the alert log entries as stated in this thread
afterwards then the checkpoints completed all at once

Wed Oct 27 11:37:15 Pacific Daylight Time 2010
Beginning log switch checkpoint up to RBA [0x10bca.2.10], SCN: 1263038699
Wed Oct 27 11:37:15 Pacific Daylight Time 2010
Thread 1 advanced to log sequence 68554 (LGWR switch)
Current log# 1 seq# 68554 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_01A.LOG
Current log# 1 seq# 68554 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_01B.LOG
Wed Oct 27 11:37:26 Pacific Daylight Time 2010
Thread 1 cannot allocate new log, sequence 68555
Checkpoint not complete
Current log# 1 seq# 68554 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_01A.LOG
Current log# 1 seq# 68554 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_01B.LOG
Wed Oct 27 11:37:26 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bc7.2.10], SCN: 1263032435
Wed Oct 27 11:37:27 Pacific Daylight Time 2010
Beginning log switch checkpoint up to RBA [0x10bcb.2.10], SCN: 1263040775
Wed Oct 27 11:37:27 Pacific Daylight Time 2010
Thread 1 advanced to log sequence 68555 (LGWR switch)
Current log# 2 seq# 68555 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_02A.LOG
Current log# 2 seq# 68555 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_02B.LOG
Wed Oct 27 11:37:40 Pacific Daylight Time 2010
Thread 1 cannot allocate new log, sequence 68556
Checkpoint not complete
Current log# 2 seq# 68555 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_02A.LOG
Current log# 2 seq# 68555 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_02B.LOG
Wed Oct 27 11:37:40 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bc8.2.10], SCN: 1263034573
Wed Oct 27 11:37:41 Pacific Daylight Time 2010
Beginning log switch checkpoint up to RBA [0x10bcc.2.10], SCN: 1263042841
Wed Oct 27 11:37:41 Pacific Daylight Time 2010
Thread 1 advanced to log sequence 68556 (LGWR switch)
Current log# 4 seq# 68556 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_04A.LOG
Current log# 4 seq# 68556 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_04B.LOG
Wed Oct 27 11:37:52 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bc9.2.10], SCN: 1263036633
Wed Oct 27 11:37:53 Pacific Daylight Time 2010
Beginning log switch checkpoint up to RBA [0x10bcd.2.10], SCN: 1263044915
Wed Oct 27 11:37:53 Pacific Daylight Time 2010
Thread 1 advanced to log sequence 68557 (LGWR switch)
Current log# 3 seq# 68557 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_03A.LOG
Current log# 3 seq# 68557 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_03B.LOG
Wed Oct 27 11:38:05 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bca.2.10], SCN: 1263038699
Wed Oct 27 11:38:06 Pacific Daylight Time 2010
Beginning log switch checkpoint up to RBA [0x10bce.2.10], SCN: 1263046977
Wed Oct 27 11:38:06 Pacific Daylight Time 2010
Thread 1 advanced to log sequence 68558 (LGWR switch)
Current log# 5 seq# 68558 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_05A.LOG
Current log# 5 seq# 68558 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_05B.LOG
Wed Oct 27 11:38:19 Pacific Daylight Time 2010
Thread 1 cannot allocate new log, sequence 68559
Checkpoint not complete
Current log# 5 seq# 68558 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_05A.LOG
Current log# 5 seq# 68558 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_05B.LOG
Wed Oct 27 11:38:19 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bcb.2.10], SCN: 1263040775
Wed Oct 27 11:38:20 Pacific Daylight Time 2010
Beginning log switch checkpoint up to RBA [0x10bcf.2.10], SCN: 1263049037
Wed Oct 27 11:38:20 Pacific Daylight Time 2010
Thread 1 advanced to log sequence 68559 (LGWR switch)
Current log# 1 seq# 68559 mem# 0: K:\ORACLE\ORADATA\LLPROD\REDO_01A.LOG
Current log# 1 seq# 68559 mem# 1: I:\ORACLE\ORADATA\LLPROD\REDO_01B.LOG
Wed Oct 27 11:38:42 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bcc.2.10], SCN: 1263042841
Wed Oct 27 11:42:57 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bcd.2.10], SCN: 1263044915
Wed Oct 27 11:43:09 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bce.2.10], SCN: 1263046977
Wed Oct 27 11:43:21 Pacific Daylight Time 2010
Completed checkpoint up to RBA [0x10bcf.2.10], SCN: 1263049037



******************************************************
Redo Logs (Redo Log Groups/Status/Size)
******************************************************

Member Member Group Group
Group# Status Archived Sequence# Members Bytes MBytes Bytes MBytes
---------- ---------------- -------- ---------- ---------- ---------------- ------- -------------- -------
1 INACTIVE YES 68549 2 134,217,728 128 268,435,456 256
2 CURRENT NO 68550 2 134,217,728 128 268,435,456 256
3 INACTIVE YES 68547 2 134,217,728 128 268,435,456 256
4 INACTIVE YES 68546 2 134,217,728 128 268,435,456 256
5 INACTIVE YES 68548 2 134,217,728 128 268,435,456 256
---------------- ------- -------------- -------
sum 671,088,640 640 1,342,177,280 1,280

Can you tell me where i need to look in order to determine what the cause of "Checkpoint not complete" is ?

Wow !

Thanks Tom for taking the time to assit me

When you advised as one of the options to add more redo files, did you mean additional group(s) or additonal members within the exiting groups ?

Additional groups.

Dear Sir,

In above explanation regarding checkpoint you said that the block created by CTAS goes directly to disk and than later in the next paragraph you mention

"...The create table as select's you are running are filling up B like crazy. DBWR is doing a checkpoint - but hasn't gotten to block 42 yet (there were lots of blocks to flush)."


Do you mean to say that the redo which is produce during CTAS is to protect undo related to data dictionary?

Could you please explain for what redo is generate during CTAS?


Many thanks

Thanks Tom and Manoj Kaparwan

I was also looking at the OPTIMAL_LOGFILE_SIZE as mentioned above in v$instance_recovery and according to it i need 4GB of REDO:

select OPTIMAL_LOGFILE_SIZE "RedoSize" from v$instance_recovery;

RedoSize
----------
4342

In your opinion, how much stock should I place in this value ?
I would have to add about another 3GB of REDO, if i go by the value.

Thanks
Jim

Just a thank you for your time

Jim

Hello,

I've followed your advice and added a new logfile group, but the problem is still hanging around (certainly less frequent but still there).
The instance is a migration from and old server to a new one and from 9i to 11gR2, and we have the exact same workload against the instance, but I can't find even once the problem into the old instance (9i) alert.log ! the only difference (concerning logfiles) between the two configuration is multiplexing, with 9i we had only two copies and then with 11g we have 3 copies of the logfiles. I'm wondering if in that matter multiplexing can play a role ?

I gone through this discussions,most of time tom recommend sizing log files or increasing number for handling issues like checkpoing not complete, can tom suggest fast_mttr_target parameter helps in this case if it is not set and we are getting the error,
2)if we enable fast_mttr_target parameter can it help in reducing number of redo logs during batch job or it will have no effect
thanks

Hi,

You wrote in your last book checkpoint not complete messages are bad and the database basically freezes up until allocate a new log. I'm seeing many Thread 1 cannot allocate new log, sequence xxxxx without being accompanied by the checkpoint message. What does these mean? Is it still bad? I assume this means I still need to add more redo logs.

Thanks.

It seems to be coinciding with our archivelog backups:

Starting control autobackup
Control autobackup written to SBT_TAPE device
        comment 'API Version 2.0,MMS Version 5.3.3.0',
        media '542110'
        handle 'OCMGW01P_c-3268357615-20110504-3d.bkp'
Wed May  4 15:45:11 2011
ALTER SYSTEM ARCHIVE LOG
Wed May  4 15:45:11 2011
Thread 1 cannot allocate new log, sequence 24243
Private strand flush not complete
  Current log# 2 seq# 24242 mem# 0: /ocmgw01p/oralogs01/redoOCMGW01P_02.log
  Current log# 2 seq# 24242 mem# 1: /ocmgw01p/oralogs02/redoOCMGW01P_02.log
Wed May  4 15:45:11 2011
Thread 1 advanced to log sequence 24243 (LGWR switch)
  Current log# 3 seq# 24243 mem# 0: /ocmgw01p/oralogs02/redoOCMGW01P_03.log
  Current log# 3 seq# 24243 mem# 1: /ocmgw01p/oralogs03/redoOCMGW01P_03.log
Wed May  4 15:45:11 2011
ALTER SYSTEM ARCHIVE LOG
Wed May  4 15:45:11 2011
Thread 1 cannot allocate new log, sequence 24244
Private strand flush not complete
  Current log# 3 seq# 24243 mem# 0: /ocmgw01p/oralogs02/redoOCMGW01P_03.log
  Current log# 3 seq# 24243 mem# 1: /ocmgw01p/oralogs03/redoOCMGW01P_03.log
Wed May  4 15:45:11 2011

Tom,

If we get checkpoint not complete error. Is it possible that committed data will not be wriiten to the disk?

Tom,

In the past redolog files where put on alternating drive letters while archive logs where put on a single drive. We saw an improvement when loading a large number or records from one Oracle DB to another.

Why log? The data was being moved from SDE (spacial database engine) database to a non SDE database. Logically an Oracle link can not move a source data type to a destination where that datatype is not. Because of online updates to other parts of the table, the table cannot be taken offline to load.

We are looking at SSD drives. Putting all the redologs on one drive seems ok. Faith in hardware has gone way up since 1980.

My concern is that testing will show no difference whith putting all the redo logs on one drive untill the user creates a task that was not tested for.

I know there are few to none rules of thumb as "my milage may vary" but any thoughts would be appreciated.

Windows 2008R2, Oracle 11gR2 for the destination, IBM supplied vendor package on the destination so modifications / tuning is difficult at best.

Thanks in advance.

Hi,

Thanks for the quick response. Yea the SSD are great for IOPS and random reads. Without having tried them – hmmm - their throughput 6gb/s may be maxed out. Actually the network may be the limiting factor. We only have a 10Gig-E, not the 40gig backplane of an ExaData, for the disks.

As for the second part that could not be parsed (turns red) the other DBA did not understand it either. Sorry. I meant that even tons of application testing may not bring up issues. The DB works great with all the redo-logs on one SSD drive instead of separate logs on separate drives. That is *until* the user does something that was never tested for. Then performance goes to heck in a hand basket.

Looking back the question is more of a statement since everything works great under known test conditions. It’s the new ones coming out in the next upgrade that may, just may, kill performance.

As a new question on redo logs, perhaps I’m confused about disk activity with redo log reads & writes. Say users A, B and C start working. Tables are updated, rows inserted – the world is great. These changes are written to the redo logs until either a ‘commit work;’ or “snap shot too old” occurs.

If the rare “roll back” occurs or when the redo logs are archived; the logs are read. Hence after a log switch, redo log N is being read while the next redo log is being written to. [warning blanket statement follows] Even with disk cache and RAID-10 there is still physical disk drive head contention. I have no proof of this, just theories.

Here SSD drives are great. No seek time, no latency time. While the network backplane may be a bottle neck – moving the redo logs to separate disk drive letters pointing to physically separate drive arrays made a difference. Well in one case. One site out of millions of ORACLE sites.

Please let me know what you think. Thanks.

One way to boost dbwr performance could be to use CIO (concurrent io) where it is supported.

Tom,

Thanks.

"But a commit will not cause a sudden flood of redo to be written as we are constantly streaming that stuff in the background." - did not know, or had forgotten, that part.

Hmmm "ARCH reads redo to archive it. Streams might read redo if you are using it." - more to look into. Hope to post real world results. We run two I/O sensitive applications.

Plus new things to play with - (clears throat) "Evaluate different archetutal constructs" - yea. That's my story and I'm sticking too it.

Happy Thanksgiving. Be back in December.

Allen

hi tom
i was wondering if redo log sequence is unique across different threads or just unique within the specific thread when redo advances in the rac ?
thanks .

Hello Tom,

One out of customers has come to us with a database set up like this:

Version 10.2.0.5 on Windows

log_checkpoint_timeout = 0 - set to zero ... how long may a block remain dirty before written to disk
fast_start_mttr_target = 0 - set to zero ... etstimated time go recover from a crash
log:_checpoint_interval = 0 - unset ... how many blocks written to redo before a checkpoint

8 redo groups with 50 MB logfiles each.

They automatically switch logfiles every half hour.

When we look at the v$log it always looks like this (with one current and the other files ACTIVE)
I know it's becase the DBWR has a lazy settnig with the above mentioned parameters, but could you explain
it to us what actually happens when the 3 params are 0.

SQL> select * from v$log;
    GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- -------------------
         1          1      37626  262144000          2 YES ACTIVE              1233427710 03 04 2012 09:49:07
         2          1      37627  262144000          2 YES ACTIVE              1233451270 03 04 2012 10:19:10
         3          1      37628  262144000          2 YES ACTIVE              1233468362 03 04 2012 10:49:10
         4          1      37629  262144000          2 YES ACTIVE              1233486682 03 04 2012 11:19:09
         5          1      37630  262144000          2 YES ACTIVE              1233502929 03 04 2012 11:49:09
         6          1      37631  262144000          2 YES ACTIVE              1233520608 03 04 2012 12:19:09
         7          1      37632  262144000          2 NO  CURRENT             1233536309 03 04 2012 12:49:08   ---<<<<<<<<
         8          1      37625  262144000          2 YES ACTIVE              1233406028 03 04 2012 09:19:08   ---<<<<  Still active after 4 hours - has DBWR fallen asleep?

At every logfile shift they get a "checkpoint not completed" - and the customer does not like it, even though we state that
this is not an error - just a wait situation. But I would like to change it for him. I'm tempted just to reset til checkpoint_timeout to default (1800 sec).
In the manual it is clearly specified that log_checkpoint_timeout is NOT set to 0 unless the mttr-taget is set (everything is 0 in this inherited system).
Or should I set the mttr_target to maybe 5-10 min instead? Or both?

I can see what is happening but could you shed some light on the 3 above parameters effect here?

best regards
Mette

Hi Tom, and thanks for the clerification.

So basicaly you say that there have not been any completed checkpoints the last 4 hours because of these weird settings ?

So we have a very very lazy dbwr ?

---

Yes, I'll go for chaning to defaults.

Mette

Hello Tom,

I have the problem "cannot allocate" also. My reason is "Private strand flush not complete". I can see from the alert.log the begining and completing of the log switch checkpoint (the data protected by log 2):

Sat Jun 02 10:00:20 2012
Thread 1 cannot allocate new log, sequence 43733
Private strand flush not complete
Current log# 2 seq# 43732 mem# 0: C:\ORACLE\ORADATA\OMGN\REDO02.RDO
Current log# 2 seq# 43732 mem# 1: C:\ORACLE\ONLINELOGS\OMGN\REDO02.RDO
Beginning log switch checkpoint up to RBA [0xaad5.2.10], SCN: 4639864294
Thread 1 advanced to log sequence 43733 (LGWR switch)
Current log# 3 seq# 43733 mem# 0: C:\ORACLE\ORADATA\OMGN\REDO03.RDO
Current log# 3 seq# 43733 mem# 1: C:\ORACLE\ONLINELOGS\OMGN\REDO03.RDO
Sat Jun 02 10:00:26 2012
Archived Log entry 87461 added for thread 1 sequence 43732 ID 0xf6b593e5 dest 1:
Archived Log entry 87462 added for thread 1 sequence 43732 ID 0xf6b593e5 dest 2:
Sat Jun 02 10:03:26 2012
Completed checkpoint up to RBA [0xaad5.2.10], SCN: 4639864294


So I suppose the checkpoint is completed (the data protected by log 2). But next time the log 2 should be used I see the same message. Could you please explain what does "Private strand flush not complete" mean in this case? Thanks.

I have a followup query regarding this error in relation to an ORA-01033 error which is being generated by the Oracle instance.
Upon trawling through the alert log, I find this error (cannot allocate new log,Checkpoint not complete) listed a minute or so AFTER the actual ORA-01033 event but nothing else directly pointing to the immediate shutdown.
Are/Can these events be related?
The earlier posts also mention that this checkpoint error suspends all processing in the database, Can you elucidate further on this aspect sil vous plait?

Tom,

I have an 11g very small idle database and I keep seeing this message in the alert log

Wed May 07 01:04:26 2014
Thread 1 cannot allocate new log, sequence 2331
Private strand flush not complete
Current log# 2 seq# 2330 mem# 0: /u01/app/oracle/oradata/finp/redo02.log
Thread 1 advanced to log sequence 2331 (LGWR switch)
Current log# 1 seq# 2331 mem# 0: /u01/app/oracle/oradata/finp/redo01.log
Wed May 07 01:04:30 2014
Archived Log entry 2263 added for thread 1 sequence 2330 ID 0x8c16f947 dest 1:
Wed May 07 01:13:50 2014
TABLE SYS.WRI$_OPTSTAT_HISTHEAD_HISTORY: ADDED INTERVAL PARTITION SYS_P422 (118) VALUES LESS THAN (TO_DATE(' 2014-05-07 06:55:28', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
Wed May 07 02:00:00 2014
Closing scheduler window
Closing Resource Manager plan via scheduler window
Clearing Resource Manager plan via parameter
Wed May 07 02:57:33 2014
Thread 1 cannot allocate new log, sequence 2332
Private strand flush not complete
Current log# 1 seq# 2331 mem# 0: /u01/app/oracle/oradata/finp/redo01.log
Thread 1 advanced to log sequence 2332 (LGWR switch)

I saw your answer on May 4, 2011 but you do not say what do to fix it or just simply ignore it. Do you do anything to resolve this?

<<<This message just means we haven't completed a LGWR write yet and something is trying to make us advance the log - we have to wait for that write to complete. >>>

I have 3 redo logs sized at 50 meg and 2 groups (defaults).