RE: cpu time and query column in tkprof output
- From: Martic Zoran <zoran_martic@xxxxxxxxx>
- To: yasbs@xxxxxxxxxxxxxx, cary.millsap@xxxxxxxxxx, oracle-l@xxxxxxxxxxxxx
- Date: Thu, 3 Feb 2005 00:52:34 -0800 (PST)
Hi Yasin,
I said earlier that the CPU time is depending on many
things (that is why you have the COST of the SQL that
is optimizer providing to you trying the best he can
:)
Lets look only the CPU time and not bother about
latches and other possible waits causing elapsed time
to be far from the CPU time.
You said about 5 sorts are done in both SQL's.
But how much time each sort consumed? No way to know
:)
You need to think that probably the sorts in the first
and the second SQL are not the same at all.
If the second SQL needed to sort 10000 rows and the
first SQL 100 you will have 1 sort per each SQL, but
more CPU time spent on the second SQL.
Or if the type of sort is different, different
algorithms.
You need to look the explain plan for both SQL's that
are giving you totally different execution plan with
sorts on different things.
DIFFERENT AMOUNT OF SORTS = DIFFERENT CPU TIME
DIFFERENT TYPE OF SORTS = DIFFERENT CPU TIME
For example what do you have in stats for:
sorts (rows)
Probably other stats should count too.
These things you do not have in trace file, even with
10046 event.
Regards,
Zoran
--- Yasin Baskan <yasbs@xxxxxxxxxxxxxx> wrote:
> I looked at the latch usage in an isolated
> environment, but they do not
> seem to be parallel to the number of buffer gets.
>
> The one with lower buffer gets resulted in 5913
> hsecs, the one with
> higher buffer gets resulted in 825 hsecs for 100
> executions of each.
>
> Latch numbers are also worse for the one with lower
> buffer gets. RUN1 is
> the one with lower buffer gets,RUN2 is the one with
> higher buffer
> gets.As you see latch usage numbers for RUN1 are
> worse.
>
> NAME
> RUN1 RUN2
> DIFF
> --------------------------------------------------
> ---------- ----------
> ----------
> LATCH.job_queue_processes parameter latch
> 1 0
> -1
> LATCH.ktm global data
> 0 1
> 1
> LATCH.ncodef allocation latch
> 1 0
> -1
> LATCH.transaction branch allocation
> 1 0
> -1
> LATCH.session switching
> 1 0
> -1
> LATCH.loader state object freelist
> 204 202
> -2
> LATCH.longop free list
> 2 0
> -2
> LATCH.virtual circuit queues
> 3 0
> -3
> LATCH.event group latch
> 12 4
> -8
> LATCH.process allocation
> 12 4
> -8
> LATCH.channel handle pool latch
> 24 8
> -16
>
> NAME
> RUN1 RUN2
> DIFF
> --------------------------------------------------
> ---------- ----------
> ----------
> LATCH.process group creation
> 24 8
> -16
> LATCH.session timer
> 19 3
> -16
> LATCH.library cache load lock
> 20 0
> -20
> LATCH.Token Manager
> 23 0
> -23
> LATCH.channel operations parent latch
> 36 12
> -24
> LATCH.sequence cache
> 36 12
> -24
> LATCH.user lock
> 48 16
> -32
> LATCH.active checkpoint queue latch
> 40 6
> -34
> LATCH.multiblock read objects
> 200 2
> -198
> LATCH.sort extent pool
> 402 203
> -199
> LATCH.session allocation
> 322 82
> -240
>
> NAME
> RUN1 RUN2
> DIFF
> --------------------------------------------------
> ---------- ----------
> ----------
> LATCH.redo writing
> 712 351
> -361
> LATCH.checkpoint queue latch
> 598 164
> -434
> LATCH.session idle bit
> 746 166
> -580
> LATCH.messages
> 1292 590
> -702
> LATCH.list of block allocation
> 2254 1254
> -1000
> LATCH.transaction allocation
> 2871 1573
> -1298
> LATCH.dml lock allocation
> 6306 3506
> -2800
> LATCH.undo global data
> 7316 4231
> -3085
> LATCH.redo allocation
> 7445 4253
> -3192
> LATCH.shared pool
> 9310 4959
> -4351
> LATCH.enqueue hash chains
> 12333 6826
> -5507
>
> NAME
> RUN1 RUN2
> DIFF
> --------------------------------------------------
> ---------- ----------
> ----------
> LATCH.cache buffers lru chain
> 32883 25895
> -6988
> LATCH.enqueues
> 16234 8912
> -7322
> LATCH.row cache objects
> 57411 32360
> -25051
> LATCH.library cache
> 100992 55926
> -45066
> LATCH.cache buffers chains
> 811950 595768
> -216182
>
> -----Original Message-----
> From: oracle-l-bounce@xxxxxxxxxxxxx
> [mailto:oracle-l-bounce@xxxxxxxxxxxxx] On Behalf Of
> Cary Millsap
> Sent: Wednesday, February 02, 2005 4:45 PM
> To: oracle-l@xxxxxxxxxxxxx
> Subject: RE: cpu time and query column in tkprof
> output
>
> Yasin,
>
> A couple of things to consider:
>
> 1. Don't forget that Oracle gets its CPU consumption
> information from
> getrusage() (or times(), depending on the port),
> which on most systems
> acquires the rusage data by polling. See Optimizing
> Oracle Performance =
> =3D
> pages
> 161-165 for the details. Thus, when you have small
> CPU consumption =3D
> numbers
> (say, less than half a second), you can't really
> trust what you're =3D
> seeing in
> a single sample measurement. You'll get a better
> idea of what's really
> happening either by enabling microstate accounting
> (if you're using
> Solaris), or by taking several sample measurements
> for the same =3D
> statement.
>
> 2. Don't forget to look at latch acquisition
> numbers, too, like Tom =3D
> Kyte's
> runstats or our OP101 course tool kit gives you. The
> latch acquisition =
> =3D
> count
> is a high-quality indicator of how well the
> statement
=== message truncated ===
__________________________________
Do you Yahoo!?
Meet the all-new My Yahoo! - Try it today!
http://my.yahoo.com
--
//www.freelists.org/webpage/oracle-l
Other related posts:
