Solved

Can not allocate log, archival required

Posted on 2001-08-21
21
3,422 Views
Last Modified: 2008-03-10
Oracle 8.1.5.0/Windows 2000 Server/2 CPU
A week ago I switched my database to ARCHIVELOG mode. I made directory c:\backup and told Oracle to write the archived redo logs there. For a week I've collected about 1.5 GB redo logs. And suddenly (about 09:00 AM) today a message appeared:
?=============================================================================?
|                                                                             |
|   Warning - The following error occured during ORACLE redo log archival:    |
|                                                                             |
L=============================================================================-
ORACLE Instance stemoco - Can not allocate log, archival required
?=============================================================================?
|                     Press <ENTER> to acknowledge message.                   |
L=============================================================================-
And the instance halted. After restart it become working again, for an hour, and then - ppof! Again the same message. The message has no error code, the search in Oracle docs gave nothing. The redo logs are successfully archived until 08:21 AM (today). The online redo log files are dated as the last restart of the server. I switched back to NOARCHIVELOG, so I hope the DB will work today. But that's not a solution.
I have 20 GB free on c:. No permitions are changed - it fully read/writeable.

If someone has any idea what is this all about, please give me a suggestion.

Rgds,
Frodo
0
Comment
Question by:FrodoBeggins
  • 12
  • 3
  • 3
  • +3
21 Comments
 
LVL 1

Expert Comment

by:i020242
ID: 6409139
Hi,

this message is interpreted as follows:
Oracle has used all the online redo logs and waits for the archiver to archive one, so Iracle will use it and thus overwrite it.

This message has nothing to do with free space of your drives.

Can you tell me how many redo logs you have? What size do they have?

The solution do your problem is either enlargement of your redo logs or creation of new ones. This is not problem, as this type of error relates to the use of your db.

Cheers,
J.K
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409258
I have the default 2 redo logs, 1MB each. The time from 6:00 AM to 11:00 AM is the less-intensive in data-writes. I have 10 snapshot servers, and this is the master server. All the replication activities are suspended at the morning, so the acountants can take any information they need for the previous days. As I said, it takes 40 minutes to 1 hour for the online redo log to get full/need switch. I wonder where is the archiver to archive the logs?

In 08:22 I've restarted the database with the "immediate" option. Maybe that counts. But for the whole week of working in ARCHIVELOG mode I have 2 succesfull restarts with ABORT (!) option. No mess after them, the database makes instance recovery (I guess) and everything's fine. Once I decided to make the things "as written in the big books" and - Ha!

I'm afrait even after I do more/bigger online redo logs the archiver process can get "asleep" again. Since it couldn't archive 1 MB in an hour this morning. How can I wake it up? The second restart couldn't help. Even the whole OS restart couldn't wake it up. What should/shouldn't I do for smooth work in ARCHIVELOG mode? Maybe I need OS scheduled job to archive ONLINE redo logs each 2 minutes or so?

Rgds,
Frodo
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409264
I know archiving the online redo logs is definitely bad idea. I just don't know what is the good idea :)

Rgds,
Frodo
0
 
LVL 1

Expert Comment

by:i020242
ID: 6409299
Hi again,

As far as I know, at the moment the error occured there must have been high database activity, even a single transaction producing a lot of redo logs.
A possible reason for the 'sleeping' archiver can be slow disks.
However I believe that if you enlarge/create more redo logs the problem will be solved. I have experienced this problem and I am OK now by the enlargement of the redos.

You can try it out and see if it works, you have nothing to lose.

For how long did you wait before shutting down the system with the immediate option?

Good luck,
J.K
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409367
As I said, this is possibly the most LOW-ACTIVITY time for the database.

Slow disks doesent's seem reasonable. I have IBM UltraStar SCSI 160 Disks in RAID! And, even if it was floppy disk it wouldn't need 1 hour to archive 1 MB file. Besides I deleted all old archived redo-logs (older than yesterday), which is more than 1 GB, in less than a second - so it is not a bug in the RAID or HDD firmware - the disk operations were good.

Anyway, I'll try it this evening.

The shutdown took some seconds. Before that I looked to the sessions. There were no active sessions, except mine and some system sessions.

Do you have any idea which process is responsible for archiving? Is it some kind of job, or what?

Rgds,
Frodo
0
 
LVL 1

Expert Comment

by:i020242
ID: 6409444
Hi,

the process responsible for archiving is the Archiver process.

However on Win2000 it is not isolated, thus you cannot see it anywhere. It is automatically started when the Oracle opens. If you were on Unix you would see an arch process running, but now you cannot. Archiver is an Oracle process, and the only thing you can do with that is to create additional slaves that would assist archiver in accomplishing its job.

Good luck again
J.K
0
 
LVL 3

Accepted Solution

by:
UsamaMunir earned 150 total points
ID: 6409487
Hi!
What i think is your Redo logs are too few.The Archiver (ARCH) process is  resposible for archiving the Redolog files.It is NOT a Job. If it can not archive  then ur database instance hangs. There are two possibilities that this problem may arise

1) The space on the Archiving Disk is full and you need to add more space.? (We def. know you dont have this problem).

2) The second reason is the ARCH process is waiting till the REDOLOG file is free for archiving. This situation may arise if the status of that particular Redolog file is 'ACTIVE' which means information in this redolog file still needs to be written by the LGWR process  on to the disk. You can check on the time of error if the Status of the REDOLOG file is active as follows

SQL> select * from v$log;

   GROUP#   THREAD# SEQUENCE#     BYTES   MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIM
--------- --------- --------- --------- --------- --- ---------------- ------------- ---------
        1         1      1204   1048576         1 NO  ACTIVE               1605082 17-AUG-01
        2         1      1205   1048576         1 NO  INACTIVE               1625175 20-AUG-01
        3         1      1206   1048576         1 NO  CURRENT                1645230 20-AUG-01



'Current' means the Redolog file is the current one, 'INACTIVE' means that all information in the redolog file is been written on the disk and it's free for archiving or whatever. 'ACTIVE' means that the logfile is still to be completely written by the LGWR on the disk.

Now the question arises why this mayb the case? as u said this the LOWEST activity time on the database, but is your CHECKPOINT interval too long? kindly check that? are your REDOLOG files on a seperate disk? The LGWR writes in very small blocks and hence mayb facing I/O contention with some other process like Archiver(ARCH). Due to this the Archiver mayb outperforming the LGWR process, and your LOGS are not freed as quickly as they are archived.this is definatly your case.

The solution (optimal) one will be

1) Put ur Redologs on a seperate disk (if they are not already)

2) Increase the number of redologs. Increasing their size may not solve the problem, but increasing the number def. will help.

3) Decrease the Checkpoint interval, so logfiles are freed up more often and during checkpoints not a huge amount of data is to be written on the disk.

5) If you do not have a Seperate disk, i will recomend reduce the redolog file size and increase their number.


I think ur problem will be solved.

Regards
UsamaMunir.

0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409643
Well. Thanks for the answers. But I wonder... Look at the time sequence:

08:21 Last archived redo log
08:22 DB restart (immediate)
09:01 First error,
      Computer restart
      (Instance recovery)
10:xx Second error
      DB restart (abort)
      (Instance recovery)
      shutdown immediate
      startup mount
      alter database noarchivelog;
      alter database open
11:01 First overwriten online redo log

Let's see. For the error to occure we need one full online redo log (current) and one offline, but still active (not all the data writen to the DB files). Well, it sounds reasonable to me that instance recovery will free up at least one of the redo logs (the one which is not current). Then the archiver whould archive it, so I must find at least ine archived redo log from about 09:03 - 09:05 AM.

Please show me where I'm wrong

Rgds,
Frodo
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409669
I have only one logical drive, made from 4 physical HDDs in RAID 1+0.
If no other answer comes this evening I'll try the folowing:
1. Switch back to ARCHIVELOG mode
2. Do some intensive data changes (try to reproduce the error)
3. Make 2 more redologs (4 total, on the same drive)
4. Try to reprodice the error again

Rgds,
Frodo
0
 
LVL 3

Expert Comment

by:UsamaMunir
ID: 6409697
'so I must find at least ine archived redo log from about 09:03 - 09:05 AM. '

i didnt get this line, plz eleborate?

0
PRTG Network Monitor: Intuitive Network Monitoring

Network Monitoring is essential to ensure that computer systems and network devices are running. Use PRTG to monitor LANs, servers, websites, applications and devices, bandwidth, virtual environments, remote systems, IoT, and many more. PRTG is easy to set up & use.

 

Expert Comment

by:ksskanth
ID: 6409773
Have u tried this

1) Start your database in Archive log mode
2) switch between your log files by forcing it by
   alter system switch logfile;
3) check whether archiving is happening properly and the status of log files are changing.
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409790
Sorry. Type error.
"I must find at least one archived redo log from about 09:03 - 09:05 AM."

That is the time after the first restart. I guess Windows shutdown makes (worst case) "shutdown abort" to the database. After windows starts again (and the database service starts again) instance recovery should be done. The instance recovery writes the data from the redo logs to the database. So no redo log should stay "active" after instance recovery, except  the "current", maybe. Right?

Rgds,
Frodo
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409805
ksskanth: No, I haven't. I'll try it right after I restart in ARCHIVELOG mode. But remember, I have about a week of succesfull redo log archival. That's about 1.5 GB (nearly 1500 files, 1MB each) archived redo logs.

Rgds,
Frodo
0
 
LVL 3

Expert Comment

by:UsamaMunir
ID: 6409814
Yes true no redo log should stay 'ACTIVE' after a restart. You got the second error at 10:00, at that time One of ur redologs will be active and one current.
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409872
Here's what I found In the log file
**************** previous restart (abort) (Friday) ***************
....
/* OracleOEM */ ALTER DATABASE MOUNT
Fri Aug 17 07:53:56 2001
Successful mount of redo thread 1, with mount id 360854100.
Fri Aug 17 07:53:56 2001
Database mounted in Exclusive Mode.
Completed: /* OracleOEM */ ALTER DATABASE MOUNT
archiving is enabled
ARCH: changing ARC0 KCRRNOARCH->KCRRSCHED
ARCH: STARTING ARCH PROCESSES
ARCH: changing ARC0 KCRRSCHED->KCRRSTART
ARCH: invoking ARC0
Fri Aug 17 07:53:56 2001
ARC0: changing ARC0 KCRRSTART->KCRRACTIVE
ARC0 started with pid=16
Fri Aug 17 07:53:56 2001
ARCH: Initializing ARC0
ARCH: ARC0 invoked
Fri Aug 17 07:53:56 2001
ARC0: Archival started
Fri Aug 17 07:53:57 2001
ARCH: STARTING ARCH PROCESSES COMPLETE
sql: prodding the archiver
Fri Aug 17 07:53:57 2001
ARC0: received prod
Fri Aug 17 07:53:57 2001
/* OracleOEM */ ALTER DATABASE OPEN
Fri Aug 17 07:53:57 2001
Picked broadcast on commit scheme to generate SCNs
Fri Aug 17 07:53:57 2001
Thread 1 opened at log sequence 49584
  Current log# 2 seq# 49584 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG
Successful open of redo thread 1.
Fri Aug 17 07:53:57 2001
sql: prodding the archiver
Fri Aug 17 07:53:57 2001
ARC0: received prod
Fri Aug 17 07:53:57 2001
SMON: enabling cache recovery
SMON: enabling tx recovery
Fri Aug 17 07:53:58 2001
Completed: /* OracleOEM */ ALTER DATABASE OPEN
Fri Aug 17 07:55:09 2001
LGWR: prodding the archiver
Thread 1 advanced to log sequence 49585
  Current log# 1 seq# 49585 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
Fri Aug 17 07:55:09 2001
ARC0: received prod
ARC0: Beginning to archive log# 2 seq# 49584
ARC0: Completed archiving log# 2 seq# 49584
ARC0: re-scanning for new log files
...
**************** end of previous restart (Friday) ***************


Here I see ARCH is started after the database is mounted and before the database is open. Now for today's (immediate) restart:


**************** today's first restart (immediate) ***************
...
/* OracleOEM */ ALTER DATABASE MOUNT
Tue Aug 21 08:27:21 2001
Successful mount of redo thread 1, with mount id 361221929.
Tue Aug 21 08:27:21 2001
Database mounted in Exclusive Mode.
Completed: /* OracleOEM */ ALTER DATABASE MOUNT
Tue Aug 21 08:27:21 2001
/* OracleOEM */ ALTER DATABASE OPEN  
Picked broadcast on commit scheme to generate SCNs
Tue Aug 21 08:27:21 2001
Thread 1 opened at log sequence 51042
  Current log# 2 seq# 51042 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG
Successful open of redo thread 1.
Tue Aug 21 08:27:21 2001
SMON: enabling cache recovery
SMON: enabling tx recovery
Tue Aug 21 08:27:22 2001
Completed: /* OracleOEM */ ALTER DATABASE OPEN
Tue Aug 21 08:27:26 2001
Thread 1 advanced to log sequence 51043
  Current log# 1 seq# 51043 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
Tue Aug 21 08:35:10 2001
Thread 1 cannot allocate new log, sequence 51044
All online logs needed archiving
  Current log# 1 seq# 51043 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
Dump file C:\Oracle\admin\STEMOCO\bdump\stemocoALRT.LOG
Tue Aug 21 09:01:29 2001
...
**************** end of today's first restart ***************

Here you can see ARCH is not started, and I have no idea why. The message appeared, and half an hour later I see it. The facts:

1) The DB is in archivelog mode (otherwise it wouldn't need archival)
2) The Arch process is not started.

Any comment?

Rgds,
Frodo
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6409919
Maybe the question got too complicated. It's not changed, but Now I see what I'm asking. I'm increasing the points...

Rrds,
Frodo
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6410244
Well, folks, I think I can see the picture. I compiled a timeline from 3 log files: Bacground dump, Archive log and User dump:
Time     File                 Action
08:14:26     Background dump     Thread 1 advanced to log sequence 51040
08:14:26     Background dump     Current log# 2 seq# 51040 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG
08.14.27     Archive log     ARC0: Begin archiving log# 1 seq# 51039 thrd# 1
08:21:49     Background dump     Thread 1 advanced to log sequence 51041
08:21:49     Background dump     Current log# 1 seq# 51041 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
08.21.49     Archive log     ARC0: archiving log# 2 seq# 51040 thrd# 1
08:24:58     Background dump     Thread 1 cannot allocate new log, sequence 51042
08:24:58     Background dump     Checkpoint not complete
08:24:58     Background dump     Current log# 1 seq# 51041 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
08:24:58     Background dump     LGWR: prodding the archiver
08:24:58     Background dump     Thread 1 advanced to log sequence 51042
08:24:58     Background dump     Current log# 2 seq# 51042 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG
08.25.00     Archive log     ARC0: archiving log# 1 seq# 51041 thrd# 1
08:26:54     Background dump     Shutting down instance (immediate)
08:26:54     Background dump     Thread 1 closed at log sequence 51042
08:26:54     Background dump     ARCH shutting down
08:27:16     Background dump     Database mounted in Exclusive Mode.
08:27:21     Background dump     Thread 1 opened at log sequence 51042
08:27:21     Background dump     Current log# 2 seq# 51042 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG
08:27:22     Background dump     database open
08:27:26     Background dump     Thread 1 advanced to log sequence 51043
08:27:26     Background dump     Current log# 1 seq# 51043 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
08:35:10     Background dump     Thread 1 cannot allocate new log, sequence 51044
08:35:10     Background dump     All online logs needed archiving
08:35:10     Background dump       Current log# 1 seq# 51043 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
09:00     **********     Computer restarted
09:01:33     Background dump     Database mounted in Exclusive Mode.
09:01:37     Background dump     alter database open
09:01:37     Background dump     Beginning crash recovery of 1 threads
09:01:37     Background dump     Thread recovery: start rolling forward thread 1
09:01:37     Background dump     Recovery of Online Redo Log: Thread 1 Group 1 Seq 51043 Reading mem 0
09:01:37     Background dump     Mem# 0 errs 0: C:\ORACLE\ORADATA\STEMOCO\REDO01.LOG
09:01:38     Background dump     Thread recovery: finish rolling forward thread 1
09:01:38     Background dump     Thread recovery: 239 blocks read, 200 blocks written
09:01:38     Background dump     Crash recovery completed successfully
09:01:38     Background dump     ARCH: Beginning to archive log# 2 seq# 51042
09:01:38     Background dump     ARCH: Completed archiving log# 2 seq# 51042
09:01:39     Background dump     Thread 1 advanced to log sequence 51044
09:01:39     Background dump     Thread 1 opened at log sequence 51044
09:01:39     Background dump     Current log# 2 seq# 51044 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG
09.01.39     User  dump     ARCH: archiving log# 2 seq# 51042 thrd# 1
09:01:42     Background dump     alter database open
09:52:53     Background dump     Thread 1 cannot allocate new log, sequence 51045
09:52:53     Background dump     All online logs needed archiving
09:52:53     Background dump     Current log# 2 seq# 51044 mem# 0: C:\ORACLE\ORADATA\STEMOCO\REDO02.LOG

(I'll explain my suggestions...)
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6410308
08:24:58 error occures. Checkpoint not complete. Message is shown onscreen. Unfortunately the server is in another room, it's monitor is turned off. ARCH is temporarely disabled until someone acknowledges the message

08:26:54 I restart the database (distantly, using OEM). ARCH is not started

After that everytning goes to hell.

The moral: never restart distantly server in ARCHIVELOG mode. Right?

Rgds,
Frodo
0
 

Expert Comment

by:sgraham
ID: 6410701
Do you have log_archive_start=true in the init.ora?

This parameter should ensure that the ARCH process is started when the DB starts up.

Also you could try

ALTER SYSTEM ARCHIVE LOG START

this starts up the archive processes... (different from ALTER DATABASE ARCHIVELOG which changes log mode)

ALTER SYSTEM ARCHIVE LOG STOP will also stop the process but leave the mode unchanged...
0
 

Expert Comment

by:johnnyce
ID: 6415855
Hi, FrodoBeggins,

To add to sqraham's comments:

The "log_archive_start=true" in the init<sid>.ora will ensure that automatic redo log archiving is permanently enabled.  The "ALTER SYSTEM ARCHIVE LOG START" will enable automatic redo log archiving, but if the init<sid>.ora parameter does not exist or is set to "false" (which is the default), automatic redo log archiving will be disabled the next time you bounce the database instance.  To verify the current status of automatic redo log archiving, in svrmgr you can use "archive log list".

I hope this helps.
0
 
LVL 2

Author Comment

by:FrodoBeggins
ID: 6416283
Thanks everybody for the help. I accept UsamaMunir's comment as an answer, because he helped me to understand what, in fact, happened. The suggestion of preventing that happen again is good too. Now I have 4 redo logs

Thanks everybody again. Now I know a little more 'bout Oracle  (-:

Rgds,
Frodo
0

Featured Post

PRTG Network Monitor: Intuitive Network Monitoring

Network Monitoring is essential to ensure that computer systems and network devices are running. Use PRTG to monitor LANs, servers, websites, applications and devices, bandwidth, virtual environments, remote systems, IoT, and many more. PRTG is easy to set up & use.

Join & Write a Comment

Note: this article covers simple compression. Oracle introduced in version 11g release 2 a new feature called Advanced Compression which is not covered here. General principle of Oracle compression Oracle compression is a way of reducing the d…
Have you ever had to make fundamental changes to a table in Oracle, but haven't been able to get any downtime?  I'm talking things like: * Dropping columns * Shrinking allocated space * Removing chained blocks and restoring the PCTFREE * Re-or…
This video shows how to Export data from an Oracle database using the Datapump Export Utility.  The corresponding Datapump Import utility is also discussed and demonstrated.
This video shows how to Export data from an Oracle database using the Original Export Utility.  The corresponding Import utility, which works the same way is referenced, but not demonstrated.

759 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question

Need Help in Real-Time?

Connect with top rated Experts

20 Experts available now in Live!

Get 1:1 Help Now