Re: help needed diagnosing problem

First Q)
do:
alter system set timed_statistics=true;

Fire the process and when you realize that your in a "long cycle", execute:

    sys.dbms_system.set_ev(SID,SERIAL#,10046,4,'')     OR sys.dbms_system.set_sql_trace_in_session(SID,SERIAL#,TRUE); use the set_ev if you want to "see" the value of any bind variables in the trace file and use the set_sql_... call if you do not care about them.

This will turn on tracing for the session and write a trace file in user_dump_dest.
Let this go for a long while or until you hit MAX_DUMP_FILE_SIZE.

Turn off tracing with:

    sys.dbms_system.set_ev(SID,SERIAL#,10046,0,'') for the first method and sys.dbms_system.set_sql_trace_in_session(SID,SERIAL#,FALSE) for the second.

A tkprof of the resulting trace file should show where the session spent its time in the database during the "long cycle".

Second Q)
Not sure, but I wouldn't think it normal for a log switch not to have a timestamp in the alert log file.

Third Q)
The previous log switch caused a checkpoint to start but it did not complete in time to have another smooth log switch. If you find lots of these entries, you may want to increase the size of your logs. Doing so would allow more time for the log-switch-induced checkpoint to complete and reduce the frequency of them.

-Kevin

<ed.stevens_at_home.com> wrote in message news:90ofv2$lm8$1_at_nnrp1.deja.com...
> A curious item just presented to me . . .
>
> A data warehouse application running a batch "aggregation." It reads
> several year's worth of claim data from one table. For each month
> represented in this input data, it deletes corresponding data from
> another table, then re-inserts new data as read from the original table.
> It commits after the delete and after two months worth of inserts. It
> writes a sequential run-time log msg after each cycle (2 months of data)
> is complete. The amount of data in each cycle varies from c. 16,000 to
> c. 190,000 records.
>
> The run-time log shows that each two-month chunk of data normally
> completes in 1 to 4 minutes, depending on data volume. About an hour
> into the process, we suddenly get one cycle that takes 5 HOURS to
> complete, then it falls back into the 1 to 3 minute per cycle. The
> amount of data processed during this long stretch is at the higher end
> of the range, but not the largest by any means. (The log I have in front
> of me shows the 5-hour cycle processed 134,000 records, while previous
> cycles processed up to 180,000 in 3 to 4 minutes.) A search of the
> alert log showed only a number of log switches during this time.
>
> One thing that I've always found curious about the alert logs is that
> they will show a number of log switch messages between time stamps,
> like this example that takes 213 log switches over a 25 minute time
> period without a time stamp.
>
> Fri Dec 01 14:44:33 2000
> Thread 1 advanced to log sequence 342767
> Current log# 2 seq# 342767 mem# 0: X:\ORAREDO\WRPP\LOG2A.RDO
> Current log# 2 seq# 342767 mem# 1: Y:\ORAREDO\WRPP\LOG2B.RDO
> Thread 1 advanced to log sequence 342768
> Current log# 3 seq# 342768 mem# 0: X:\ORAREDO\WRPP\LOG3A.RDO
> Current log# 3 seq# 342768 mem# 1: Y:\ORAREDO\WRPP\LOG3B.RDO
> Thread 1 advanced to log sequence 342769
> Current log# 1 seq# 342769 mem# 0: X:\ORAREDO\WRPP\LOG1A.RDO
> Current log# 1 seq# 342769 mem# 1: Y:\ORAREDO\WRPP\LOG1B.RDO
> Thread 1 advanced to log sequence 342770
> Current log# 2 seq# 342770 mem# 0: X:\ORAREDO\WRPP\LOG2A.RDO
> Current log# 2 seq# 342770 mem# 1: Y:\ORAREDO\WRPP\LOG2B.RDO
>
> <Snip 208 more log switch messages>
>
> Thread 1 advanced to log sequence 342979
> Current log# 1 seq# 342979 mem# 0: X:\ORAREDO\WRPP\LOG1A.RDO
> Current log# 1 seq# 342979 mem# 1: Y:\ORAREDO\WRPP\LOG1B.RDO
> Fri Dec 01 15:09:48 2000
> Thread 1 advanced to log sequence 342980
> Current log# 2 seq# 342980 mem# 0: X:\ORAREDO\WRPP\LOG2A.RDO
> Current log# 2 seq# 342980 mem# 1: Y:\ORAREDO\WRPP\LOG2B.RDO
> Fri Dec 01 15:28:43 2000
>
>
> So, I have 3 questions:
>
> First, can anyone think of anything I should look at to figure out why
> this application suddenly takes 5 hours to do what it had been taking
> only 5 minutes to do, and continues afterward to take only 5 minutes to
> do in the same batch run?
>
> Second, why would the alert log would post so much activity over such a
> relatively long period of time between posting time stamps? Is there
> something I can do to alter this behavior?
>
> Third, occasionally between log switch messages, the alert log gives
>
> Thread 1 cannot allocate new log, sequence 317994
> Checkpoint not complete
>
> Is this the result of cycling back around to a log file before that file
> has been written to archive?
>
> BTW, this is Oracle8, Enterprise edition, running on NT4 sp6.
>
>
> TIA.
>
> - Ed Stevens
>
>
> Sent via Deja.com http://www.deja.com/
> Before you buy.
Received on Thu Dec 07 2000 - 12:41:31 CST