RE: Timestamps in trace files (and other trace file oddities)

2003-07-28 Thread Henry Poras
Wolfgang, Thanks for the offer. You're lucky. I got to go to New Jersey for the last three days. The trace I posted was my initial run with no attempt to tune. I had just never seen such a large discrepency between the wait elapsed time and the wall clock time in the trace file. The explanation

RE: Timestamps in trace files (and other trace file oddities)

2003-07-28 Thread Wolfgang Breitling
Of course, anytime. Have fun with the CBO trace. At 01:19 PM 7/28/2003 -0800, you wrote: Wolfgang, Thanks for the offer. You're lucky. I got to go to New Jersey for the last three days. The trace I posted was my initial run with no attempt to tune. I had just never seen such a large discrepency

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Henry Poras
(Tried sending this yesterday. I'll try again) Dan, I was running a 10046 (level 12) trace on an awful piece of PeopleSoft SQL today and got some really odd results in my trace file (8.1.7). *** 2003-07-23 15:40:59.149 WAIT #1: nam='db file scattered read' ela= 0 p1=65 p2=6041 p3=18 ***

Re: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Daniel Fink
Henry, I'll make an attempt, but I am still learning a great deal about wait events and trace files. Cary, Mogens, Anjo, Tim, Jonathan, Wolfgang, et.al. are better authorities, so any corrections are very welcome. The time between waits is the elapsed time. If we equate elapsed

Re: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Tanel Poder
Hi! About the second one, you see the first read started from 6041 and was 18 blocks, the second one which was executed 7 minutes later, started from 6042 and was 17 blocks. Probably the extent boundary is at block 6059. Multiblock reads don't cross extent boundaries. So, probably your query

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Wolfgang Breitling
My interpretation would be as follows: The wait entries are written whenever a wait ends, so at 15:40:59.149 the session has just been waiting .00 seconds for a scattered read of 18 blocks. At 15:46:06.340 it just had been waiting on a latch free event. For the almost seven minutes between, it

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Henry Poras
Dan, I see what you are saying but something doesn't feel right (see, say, feel. Should be some pun in here about not making sense). CPU time of 7 minutes after a single read??? This is an ugly INSERT on a 5 table join, but that's about it. Unfortunately I don't think there is a way to

Re: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Daniel Fink
Henry, I completely agree, something did not feel right (hence my obvious reluctance). I did a very poor job of trying to explain that we cannot extrapolate system waits/activity by looking at database waits/activity. I should have learned my lesson (bad dba...go sit in the corner) from

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Henry Poras
Dan, No reason to stay in the corner (unless that's where the fridge is). I'm trying to decide where to look on the OS. When I looked at vmstat, there was no paging, and ~20% idle cpu. Maybe set up a cron to take snapshots of something(??) every few minutes? Support from the Sys Admin side

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Wolfgang Breitling
20% idle = 80% busy? How many cpus? If it is 20% idle that should lay to rest the theory that the process may wait for a cpu. But, if it is a 5-way join, maybe it is reading a set of blocks from file 65 and then collects the corresponding rows from the other 4 tables, which must be all pure

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Henry Poras
Wolfgang, There are 4 cpu's, and file# 65 block# 6041 is from the driving table of the 5 table join (all NL joins). I will take a look at v$bh to see what blocks from the other tables are in memory next time I run this. Aside from this indirect approach, any other suggestions on confirming

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Wolfgang Breitling
It's been about a decade that I have been working with AIX. There must be tools that give you a breakdown by cpu. Else you can do a ps -ef or ps aux and watch your process. If I'mm right you should see it consuming 99% cpu all the time. I have been looking after Peoplesoft systems for several

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Freeman Robert - IL
If you have a 10046 trace file, and the means to process/analyze it, then it will tell you what you need to know. If it's IO, you will see IO related waits. If they are not there, and no other significant wait events, then it's all processing time, which probably equaits to LIO's. Thats my take.

Re: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Gudmundur Josepsson
If you have a 10046 trace file, and the means to process/analyze it For processing and analyzing a 10046 trace file I think nothing compares to the Hotsos Profiler. It's very reasonably priced, too. Gudmundur -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author:

Re: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Daniel Fink
10046 Trace files are a peak into how an application and Oracle operate. In looking at one generated by a web server, I identified that the application (user) was sorting to a temporary tablespace that was dictionary/permanent without at the data dictionary. I saw a query performing DML against

Re: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Wolfgang Breitling
If the sort requires disk you'll the direct write/reads in the trace. They do not count towards LIO and PIO as they are not using the buffer pool. At 03:49 PM 7/24/2003 -0800, you wrote: Another significant area of processing can be sorting. I don't know if sort processing is counted along

RE: Timestamps in trace files (and other trace file oddities)

2003-07-24 Thread Cary Millsap
I absolutely agree with Wolfgang. This pattern of behavior in the trace file is common for applications that do an excessive amount of LIO processing. (LIO = logical I/O, or a fetch of a buffer's content from the database buffer cache.) Henry, you don't show the database call whose line was

RE: Timestamps in trace files (and other trace file oddities)

2003-07-23 Thread Henry Poras
Dan, I was running a 10046 (level 12) trace on an awful piece of PeopleSoft SQL today and got some really odd results in my trace file (8.1.7). *** 2003-07-23 15:40:59.149 WAIT #1: nam='db file scattered read' ela= 0 p1=65 p2=6041 p3=18 *** 2003-07-23 15:46:06.340 WAIT #1: nam='latch free' ela= 1