Re: help needed diagnosing problem

Another thing you might look at is why you are suddenly getting all the log switches. Do you have a batch update staring automatically? I'd guess that you are seeing locking on the table and your process is sitting waiting on a blocked delete or similar.

...neil
On Thu, 7 Dec 2000 12:41:31 -0600, "Kevin Brand" <kevin.brandx_at_tel.gte.com> wrote:

>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 - 19:28:59 CST