RE: cpu time and query column in tkprof output
- From: "Yasin Baskan" <yasbs@xxxxxxxxxxxxxx>
- To: <cary.millsap@xxxxxxxxxx>, <oracle-l@xxxxxxxxxxxxx>
- Date: Thu, 3 Feb 2005 10:30:45 +0200
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 will scale as you
=3D
add
users. I think you'll find that latch acquisition counts are roughly
proportional to logical read count.
Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *
Upcoming events:
- Performance Diagnosis 101: 2/23 Houston, 3/16 Salt Lake City
- SQL Optimization 101: 2/7 Dallas
- Hotsos Symposium 2005: March 6-10 Dallas
- Visit www.hotsos.com for schedule details...
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx =3D
[mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Yasin Baskan
Sent: Wednesday, February 02, 2005 7:55 AM
To: Martic Zoran; oracle-l@xxxxxxxxxxxxx
Subject: RE: cpu time and query column in tkprof output
I have the following statistics for the one with less cpu time and less
elapsed time:
Statistics
----------------------------------------------------------
0 recursive calls
62 db block gets
11407 consistent gets
14 physical reads
0 redo size
189 bytes sent via SQL*Net to client
791 bytes received via SQL*Net from client
3 SQL*Net roundtrips to/from client
5 sorts (memory)
1 sorts (disk)
1 rows processed
And the following statistics are for the one with more cpu time and
elapsed time:
Statistics
----------------------------------------------------------
0 recursive calls
58 db block gets
4108 consistent gets
155 physical reads
0 redo size
204 bytes sent via SQL*Net to client
657 bytes received via SQL*Net from client
3 SQL*Net roundtrips to/from client
5 sorts (memory)
1 sorts (disk)
1 rows processed
The number of sorts is the same. The one with more cpu time has 141 more
physical reads but much less buffer gets. Then the idea of focusing on
logical reads and ignoring physical reads is not true for this case. Do
you suggest using the one with more cpu&elapsed time but less buffer
gets or the one with less cpu time but more buffer gets?
-----Original Message-----
From: Martic Zoran [mailto:zoran_martic@xxxxxxxxx]=3D3D20
Sent: Wednesday, February 02, 2005 3:25 PM
To: Yasin Baskan; oracle-l@xxxxxxxxxxxxx
Subject: Re: cpu time and query column in tkprof output
Hi Yasin,
More disk reads =3D3D3D usually more elapsed time.
More sorts or more complex memory operations =3D3D3D more
CPU time
Then it looks easy to draw the conclusion, maybe not
the perfect one, but at least for the start.
What you are missing here are waits (Oracle + OS).
If you trace it with event level 10046 and using some
better profiler (ixora, ubtools, ....) then you can
narrow it even more then my simple explanation.
Regards,
Zoran
--- Yasin Baskan <yasbs@xxxxxxxxxxxxxx> wrote:
> Hi,
> =3D3D20
>=3D3D20
> I want to ask two questions about the following 2
> sql statements. The
> below tkprof output shows 2 executes for each of
> them although i
> executed each once. Is it because of the select
> statements inside the
> main select?
>=3D3D20
> =3D3D20
>=3D3D20
> My main question is; for the second query it shows
> far less buffer gets
> than the first one, but the second one has more cpu
> time and elapsed
> time. Is this meaningful? I am looking at the buffer
> gets and saying
> that the second query is better but it shows more
> elapsed time?
>=3D3D20
> How should i comment on the following output?
>=3D3D20
> =3D3D20
>=3D3D20
> =3D3D20
>=3D3D20
> SELECT COUNT (*)
>=3D3D20
> FROM faxutil.t_kfs_jobs j, faxutil.t_kfs_actions a
>=3D3D20
> WHERE j.NO =3D3D3D a.jobno
>=3D3D20
> AND a.pool_id =3D3D3D :poolname
>=3D3D20
> AND (a.jobno, a.iteration) IN (SELECT jobno,
> MAX (iteration)
>=3D3D20
> FROM
> faxutil.t_kfs_actions
>=3D3D20
> WHERE pool_id =3D3D3D
> :poolname
>=3D3D20
> GROUP BY jobno)
>=3D3D20
> AND EXISTS (
>=3D3D20
> SELECT pool_status, job_status
>=3D3D20
> FROM faxutil.t_kfs_tabstatuses
>=3D3D20
> WHERE tabno =3D3D3D :ptabno
>=3D3D20
> AND pool_status =3D3D3D a.status
>=3D3D20
> AND job_status =3D3D3D j.status)
>=3D3D20
> =3D3D20
>=3D3D20
> call count cpu elapsed disk =3D3D20
> query current
> rows
>=3D3D20
> ------- ------ -------- ---------- ----------
> ---------- ----------
> ----------
>=3D3D20
> Parse 1 0.00 0.00 0 =3D3D20
> 0 0
> 0
>=3D3D20
> Execute 2 0.00 0.00 0 =3D3D20
> 0 0
> 0
>=3D3D20
> Fetch 2 0.18 0.31 14 =3D3D20
> 11677 58
> 1
>=3D3D20
> ------- ------ -------- ---------- ----------
> ---------- ----------
> ----------
>=3D3D20
> total 5 0.18 0.31 14 =3D3D20
> 11677 58
> 1
>=3D3D20
> =3D3D20
>=3D3D20
> Misses in library cache during parse: 0
>=3D3D20
> Optimizer goal: CHOOSE
>=3D3D20
> =3D3D20
>=3D3D20
> Misses in library cache during parse: 0
>=3D3D20
> Optimizer goal: CHOOSE
>=3D3D20
> Parsing user id: 46
>=3D3D20
> =3D3D20
>=3D3D20
> Rows Row Source Operation
>=3D3D20
> -------=3D3D20
> ---------------------------------------------------
>=3D3D20
> 1 SORT AGGREGATE
>=3D3D20
> 14 FILTER
>=3D3D20
> 2768 NESTED LOOPS
>=3D3D20
> 2768 HASH JOIN
>=3D3D20
> 2767 VIEW VW_NSO_1
>=3D3D20
> 2767 SORT GROUP BY
>=3D3D20
> 2875 INDEX RANGE SCAN (object id 34317)
>=3D3D20
> 2875 INDEX RANGE SCAN (object id 34317)
>=3D3D20
> 5534 TABLE ACCESS BY INDEX ROWID T_KFS_JOBS
>=3D3D20
> 5534 INDEX UNIQUE SCAN (object id 31338)
>=3D3D20
> 14 TABLE ACCESS FULL T_KFS_TABSTATUSES
>=3D3D20
> =3D3D20
>=3D3D20
> =3D3D20
>=3D3D20
> select /*+ ordered */
>=3D3D20
> count(*)
>=3D3D20
> from
>=3D3D20
> faxutil.t_kfs_tabstatuses c,
>=3D3D20
> faxutil.t_kfs_jobs j,
>=3D3D20
> faxutil.t_kfs_actions a,
>=3D3D20
> ( select jobno, max(iteration) iteration
>=3D3D20
> from faxutil.t_kfs_actions
>=3D3D20
> where pool_id =3D3D3D :poolname
>=3D3D20
> group by jobno ) sqry1
>=3D3D20
> where
>=3D3D20
> j.no =3D3D3D a.jobno
>=3D3D20
> and a.pool_id =3D3D3D :poolname
>=3D3D20
> and a.jobno =3D3D3D sqry1.jobno
>=3D3D20
> and a.iteration =3D3D3D sqry1.iteration
>=3D3D20
> and c.tabno =3D3D3D :ptabno
>=3D3D20
> and c.pool_status =3D3D3D a.status
>=3D3D20
> and c.job_status =3D3D3D j.status
>=3D3D20
> =3D3D20
>=3D3D20
> call count cpu elapsed disk =3D3D20
> query current
> rows
>=3D3D20
> ------- ------ -------- ---------- ----------
> ---------- ----------
> ----------
>=3D3D20
> Parse 1 0.00 0.00 0 =3D3D20
> 0 0
> 0
>=3D3D20
> Execute 2 0.00 0.00 0 =3D3D20
> 0 0
> 0
>=3D3D20
> Fetch 2 0.82 1.44 31 =3D3D20
> 4565 58
> 1
>=3D3D20
> ------- ------ -------- ---------- ----------
> ---------- ----------
> ----------
>=3D3D20
> total 5 0.82 1.44 31 =3D3D20
> 4565 58
> 1
>=3D3D20
=3D3D3D=3D3D3D=3D3D3D message truncated =3D3D3D=3D3D3D=3D3D3D
=3D3D09
__________________________________=3D3D20
Do you Yahoo!?=3D3D20
Yahoo! Mail - 250MB free storage. Do more. Manage less.=3D3D20
http://info.mail.yahoo.com/mail_250
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
