redo logs: instantaneous switches
dsmcd
817 on Win2k.
I'm archiving & duplexing my redo logs. Certain days the logs
appear to be instantaneously switching, though if I look at a
log's first change # and last change #, they are different so
perhaps they're not instantaneous. I can't be sure since times
are in minutes not seconds. Either way, it's unexpected and
worrisome.
In fact, there was one full day when I had dozens of switches
every minute, all day long.
Usually, logs would switch at most two or three times on hour.
There's been no added load to the system that would come close
to accounting for such fast switching.
I shutdown and startup the instance each day, which may point to
something in the startup or shutdown effecting the logs.
I have three groups, each with one log.
Any suggestions? This has me quite concerned.
TIA,
D.
Here's some data:
Browsing the archive folder, I'll see:
POS4T001S12148.arc 1,025KB 01/22/03 8:19pm
POS4T001S12149.arc 1,025KB 01/22/03 8:46pm
POS4T001S12150.arc 1,025KB 01/22/03 8:46pm
POS4T001S12151.arc 1,025KB 01/22/03 9:29pm
POS4T001S12152.arc 1,025KB 01/22/03 9:29pm
POS4T001S12153.arc 1,025KB 01/22/03 9:30pm
POS4T001S12154.arc 1,025KB 01/22/03 9:30pm
POS4T001S12155.arc 1,025KB 01/22/03 9:31pm
POS4T001S12156.arc 1,025KB 01/22/03 9:31pm
POS4T001S12157.arc 1,025KB 01/22/03 9:49pm
POS4T001S12148.arc 1,025KB 01/22/03 9:53pm
Looking at alert logs shows
Wed Jan 22 20:03:37 2003
ARC1: Completed archiving log# 3 seq# 12147
Wed Jan 22 20:19:02 2003
Thread 1 advanced to log sequence 12149
Current log# 2 seq# 12149 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO02.LOG
Wed Jan 22 20:19:02 2003
ARC0: Beginning to archive log# 1 seq# 12148
ARC0: Completed archiving log# 1 seq# 12148
Wed Jan 22 20:46:43 2003
Thread 1 advanced to log sequence 12150
Current log# 3 seq# 12150 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO01.LOG
Wed Jan 22 20:46:43 2003
ARC0: Beginning to archive log# 2 seq# 12149
Wed Jan 22 20:46:44 2003
Thread 1 cannot allocate new log, sequence 12151
Checkpoint not complete
Current log# 3 seq# 12150 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO01.LOG
Wed Jan 22 20:46:44 2003
ARC0: Completed archiving log# 2 seq# 12149
Wed Jan 22 20:46:46 2003
Thread 1 advanced to log sequence 12151
Current log# 1 seq# 12151 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO03.LOG
Wed Jan 22 20:46:46 2003
ARC0: Beginning to archive log# 3 seq# 12150
ARC0: Completed archiving log# 3 seq# 12150
Wed Jan 22 21:29:33 2003
Thread 1 advanced to log sequence 12152
Current log# 2 seq# 12152 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO02.LOG
Wed Jan 22 21:29:33 2003
ARC0: Beginning to archive log# 1 seq# 12151
Wed Jan 22 21:29:35 2003
Thread 1 advanced to log sequence 12153
Current log# 3 seq# 12153 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO01.LOG
Wed Jan 22 21:29:35 2003
ARC0: Completed archiving log# 1 seq# 12151
ARC0: Beginning to archive log# 2 seq# 12152
Wed Jan 22 21:29:35 2003
ARC1: Beginning to archive log# 2 seq# 12152
ARC1: Failed to archive log# 2 seq# 12152
ARC1: Beginning to archive log# 2 seq# 12152
ARC1: Failed to archive log# 2 seq# 12152
Wed Jan 22 21:29:35 2003
ARC0: Completed archiving log# 2 seq# 12152
Wed Jan 22 21:30:20 2003
Thread 1 advanced to log sequence 12154
Current log# 1 seq# 12154 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO03.LOG
Wed Jan 22 21:30:20 2003
ARC0: Beginning to archive log# 3 seq# 12153
Wed Jan 22 21:30:21 2003
Thread 1 cannot allocate new log, sequence 12155
Checkpoint not complete
Current log# 1 seq# 12154 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO03.LOG
Wed Jan 22 21:30:21 2003
ARC0: Completed archiving log# 3 seq# 12153
Wed Jan 22 21:30:24 2003
Thread 1 advanced to log sequence 12155
Current log# 2 seq# 12155 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO02.LOG
Wed Jan 22 21:30:24 2003
ARC0: Beginning to archive log# 1 seq# 12154
ARC0: Completed archiving log# 1 seq# 12154
Wed Jan 22 21:31:24 2003
Thread 1 advanced to log sequence 12156
Current log# 3 seq# 12156 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO01.LOG
Wed Jan 22 21:31:24 2003
ARC0: Beginning to archive log# 2 seq# 12155
Wed Jan 22 21:31:25 2003
Thread 1 cannot allocate new log, sequence 12157
Checkpoint not complete
Current log# 3 seq# 12156 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO01.LOG
Wed Jan 22 21:31:25 2003
ARC0: Completed archiving log# 2 seq# 12155
Wed Jan 22 21:31:26 2003
Thread 1 advanced to log sequence 12157
Current log# 1 seq# 12157 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO03.LOG
Wed Jan 22 21:31:26 2003
ARC0: Beginning to archive log# 3 seq# 12156
ARC0: Completed archiving log# 3 seq# 12156
Wed Jan 22 21:49:12 2003
Thread 1 advanced to log sequence 12158
Current log# 2 seq# 12158 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO02.LOG
Wed Jan 22 21:49:12 2003
ARC0: Beginning to archive log# 1 seq# 12157
ARC0: Completed archiving log# 1 seq# 12157
Wed Jan 22 21:53:57 2003
Thread 1 advanced to log sequence 12159
Current log# 3 seq# 12159 mem# 0:
D:\ORACLE\ORADATA\POS4\REDO01.LOG
Wed Jan 22 21:53:57 2003
ARC0: Beginning to archive log# 2 seq# 12158
ARC0: Completed archiving log# 2 seq# 12158
Howard J. Rogers
result of the logs filling up through normal transactional activity, then
each archive will bethe same size as each online log. But if you've got
something or someone issuing spurious 'alter system switch logfile'
commands, then the archive produced will be much, much smaller than the
online log.
For example:
SQL> archive log list
Database log mode Archive Mode
Automatic archival Enabled
Archive destination D:\oracle\ora92\RDBMS
Oldest online log sequence 8
Next log sequence to archive 11
Current log sequence 11
SQL> alter system switch logfile;
System altered.
SQL> select group#, bytes from v$log;
GROUP# BYTES
---------- ----------
1 104857600
2 104857600
3 104857600
SQL> exit;
Disconnected from Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.1.0 - Production
C:\Documents and Settings\Howard>dir d:\oracle\ora92\rdbms\*.*
Volume in drive D is LARGE_DATA
Volume Serial Number is E8CB-D350
Directory of d:\oracle\ora92\rdbms
20/01/2003 03:54 PM 104,857,088 ARC00009.001
21/01/2003 06:17 PM 104,857,088 ARC00010.001
24/01/2003 06:56 AM 28,335,616 ARC00011.001
So, usually each archive is 100M, just as my online logs are sized. But the
last one generated, forced with a log switch, is much smaller.
Anyway, that would indicate whether you've got a rogue log switcher on your
team. If they're all the same size, then you'd have to start delving into
log miner to see what was happening on the database at the time the log
switch rate sky-rocketed.
Regards
HJR
"dsmcd" <lookin...@stopspammdormouse.net> wrote in message
news:0AXX9.991$H14....@news.uswest.net...
dsmcd
Still, there's nothing that can account for such frenetic
activity.
Any other suggestions? There's some data from alert logs and
files at the end of the message.
Thx,
D.
Howard J. Rogers
"dsmcd" <ds...@uswestmail.net> wrote in message
news:63YX9.997$H14....@news.uswest.net...
> Thanks. All logs are same size 1,024KB, same as online logs.
> Still, there's nothing that can account for such frenetic
> activity.
>
> Any other suggestions?
Not really, other than that your redo logs at only 1MB big are way, way too
small.
But that should make it really easy to use log miner to find out what was in
the log when it was switching rapidly.
Regards
HJR
dsmcd
six or eight registers. Average is a switch every 30 minutes,
which at the time I deployed seemed reasonable according to
advice and research available at the time. Guess not.
This "log miner" is something new to me. I'll look into it,
unless you mean reading the alert log for switching info, in
which case I included snips in my original message.
Good to see you again, Howard! I still miss your website. It was
invaluable to me. Sure glad I made hard copies.
D.
"Howard J. Rogers" <howard...@yahoo.com.au> wrote:
Howard J. Rogers
"dsmcd" <lookin...@stopspamdormouse.net> wrote in message
news:UwYX9.999$H14....@news.uswest.net...
> I just went with the default sizes. It's a POS database, with
> six or eight registers. Average is a switch every 30 minutes,
> which at the time I deployed seemed reasonable according to
> advice and research available at the time. Guess not.
>
> This "log miner" is something new to me.
OK. It's nothing to do with the alert log, but a set of packages that allow
you to see inside of the online redo logs.
Read up on it by all means, but the quick story is: it's a three-step
process.
1. Create a "dictionary file" (needed to map redo change vectors into plain
English statements: squiggle-squiggle-dash-dot-blah becomes 'update EMP set
sal=900'). That's execute
dbms_logmnr_d.build(<name_of_file>,<location_of_file>).
Note that the <location_of_file> parameter must match one of your settings
for the init.ora parameter utl_file_dir.
2. Build a list of logs to analyze. You can analyze just one, or dozens.
Online, archived, current. Makes no difference:
execute dbms_logmnr.add_logfile(<full_path_and_name_of_log>,
dbms_logmnr.new)
AND
execute dbms_logmnr.add_logfile(<full_path_and_name_of_log>,
dbms_logmnr.addfile)
Use the first one for the very first log you add to the list (the ".new"
initialises a new list). All other logs to be analyzed in the same run are
added with the second version of the command (".addfile" adds a file to an
already-existing list)
3. Perform the analysis:
execute
dbms_logmnr.start_logmnr(dictfilename=>'path_and_name_of_dictionary_file')
That 'path_and_name' is the full-blown version of what you created in step
1, but in the right order and looking normal. That is, if in step 1 you
created a file called 'HJRDICT.ORA', in directory 'C:\BLAH', then here you'd
enter 'c:\blah\hjrdict.ora'.
Step 3 is the one that can take time, because it actually has to trawl
through the logs and deal with the information it finds there.
At the end of step 3, you can query v$logmnr_contents, which shows you two
really important columns: SQL_REDO (what SQL statement was actualy issued,
or its logical equivalent) and SQL_UNDO (what SQL statement would you issue
to logically reverse the effect of the issued statement.
It's also got columns for the User and the time a statement was issued, so
that might help track down who is doing what.
>I'll look into it,
> unless you mean reading the alert log for switching info, in
> which case I included snips in my original message.
>
> Good to see you again, Howard! I still miss your website. It was
> invaluable to me. Sure glad I made hard copies.
>
Kind of you to say so. I'm currently being hassled about the unauthorised
copies of the former site as well now, even though they're nothing to do
with me. So this one looks set to run and run.
Regards
HJR