RE: cpu time and query column in tkprof output

From: Cary Millsap <cary.millsap_at_hotsos.com>
Date: Wed, 2 Feb 2005 08:44:58 -0600
Message-ID: <003401c50935$c79ae120$6500a8c0@CVMLAP02>

Yasin,

A couple of things to consider:

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 = pages 161-165 for the details. Thus, when you have small CPU consumption = numbers (say, less than half a second), you can't really trust what you're = 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 = statement.
Don't forget to look at latch acquisition numbers, too, like Tom = Kyte's runstats or our OP101 course tool kit gives you. The latch acquisition = count is a high-quality indicator of how well the statement will scale as you = 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_at_freelists.org =
[mailto:oracle-l-bounce_at_freelists.org]
On Behalf Of Yasin Baskan
Sent: Wednesday, February 02, 2005 7:55 AM To: Martic Zoran; oracle-l_at_freelists.org 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_at_yahoo.com]=3D20 Sent: Wednesday, February 02, 2005 3:25 PM To: Yasin Baskan; oracle-l_at_freelists.org Subject: Re: cpu time and query column in tkprof output

Hi Yasin,

More disk reads =3D3D usually more elapsed time. More sorts or more complex memory operations =3D3D 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_at_kocbank.com.tr> wrote:

> Hi,
> =3D20

>=3D20

> 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?

>=3D20

> =3D20

>=3D20

> 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?

>=3D20

> How should i comment on the following output?

>=3D20

> =3D20

>=3D20

> =3D20

>=3D20

> SELECT COUNT (*)

>=3D20

> FROM faxutil.t_kfs_jobs j, faxutil.t_kfs_actions a

>=3D20

> WHERE j.NO =3D3D a.jobno

>=3D20

> AND a.pool_id =3D3D :poolname

>=3D20

> AND (a.jobno, a.iteration) IN (SELECT jobno,
> MAX (iteration)

>=3D20


>                                       FROM

> faxutil.t_kfs_actions

>=3D20


>                                      WHERE pool_id =3D3D

> :poolname

>=3D20


>                                   GROUP BY jobno)

>=3D20

> AND EXISTS (

>=3D20


>           SELECT pool_status, job_status

>=3D20


>             FROM faxutil.t_kfs_tabstatuses

>=3D20


>            WHERE tabno =3D3D :ptabno

>=3D20


>              AND pool_status =3D3D a.status

>=3D20


>              AND job_status =3D3D j.status)

>=3D20

> =3D20

>=3D20


> call     count       cpu    elapsed       disk    =3D20

> query current
> rows

>=3D20


> ------- ------  -------- ---------- ----------

> ---------- ----------
> ----------

>=3D20


> Parse        1      0.00       0.00          0     =3D20

>    0          0

> 0

>=3D20


> Execute      2      0.00       0.00          0     =3D20

>    0          0

> 0

>=3D20


> Fetch        2      0.18       0.31         14    =3D20

> 11677         58

> 1

>=3D20


> ------- ------  -------- ---------- ----------

> ---------- ----------
> ----------

>=3D20


> total        5      0.18       0.31         14    =3D20

> 11677         58

> 1

>=3D20

> =3D20

>=3D20

> Misses in library cache during parse: 0

>=3D20

> Optimizer goal: CHOOSE

>=3D20

> =3D20

>=3D20

> Misses in library cache during parse: 0

>=3D20

> Optimizer goal: CHOOSE

>=3D20

> Parsing user id: 46

>=3D20

> =3D20

>=3D20


> Rows     Row Source Operation

>=3D20

> -------=3D20
> ---------------------------------------------------

>=3D20


>       1  SORT AGGREGATE

>=3D20


>      14   FILTER

>=3D20

> 2768 NESTED LOOPS

>=3D20


>    2768     HASH JOIN

>=3D20


>    2767      VIEW VW_NSO_1

>=3D20


>    2767       SORT GROUP BY

>=3D20


>    2875        INDEX RANGE SCAN (object id 34317)

>=3D20


>    2875      INDEX RANGE SCAN (object id 34317)

>=3D20


>    5534     TABLE ACCESS BY INDEX ROWID T_KFS_JOBS

>=3D20


>    5534      INDEX UNIQUE SCAN (object id 31338)

>=3D20


>      14    TABLE ACCESS FULL T_KFS_TABSTATUSES

>=3D20

> =3D20

>=3D20

> =3D20

>=3D20

> select /*+ ordered */

>=3D20

> count(*)

>=3D20

> from

>=3D20

> faxutil.t_kfs_tabstatuses c,

>=3D20

> faxutil.t_kfs_jobs j,

>=3D20

> faxutil.t_kfs_actions a,

>=3D20

> ( select jobno, max(iteration) iteration

>=3D20

> from faxutil.t_kfs_actions

>=3D20

> where pool_id =3D3D :poolname

>=3D20

> group by jobno ) sqry1

>=3D20

> where

>=3D20

> j.no =3D3D a.jobno

>=3D20

> and a.pool_id =3D3D :poolname

>=3D20

> and a.jobno =3D3D sqry1.jobno

>=3D20

> and a.iteration =3D3D sqry1.iteration

>=3D20

> and c.tabno =3D3D :ptabno

>=3D20

> and c.pool_status =3D3D a.status

>=3D20

> and c.job_status =3D3D j.status

>=3D20

> =3D20

>=3D20


> call     count       cpu    elapsed       disk    =3D20

> query current
> rows

>=3D20


> ------- ------  -------- ---------- ----------

> ---------- ----------
> ----------

>=3D20


> Parse        1      0.00       0.00          0     =3D20

>    0          0

> 0

>=3D20


> Execute      2      0.00       0.00          0     =3D20

>    0          0

> 0

>=3D20


> Fetch        2      0.82       1.44         31     =3D20

> 4565         58

> 1

>=3D20


> ------- ------  -------- ---------- ----------

> ---------- ----------
> ----------

>=3D20


> total        5      0.82       1.44         31     =3D20

> 4565         58

> 1

>=3D20
=3D3D=3D3D=3D3D message truncated =3D3D=3D3D=3D3D

=3D09

__________________________________=3D20

Do you Yahoo!?=3D20
Yahoo! Mail - 250MB free storage. Do more. Manage less.=3D20 http://info.mail.yahoo.com/mail_250

--
http://www.freelists.org/webpage/oracle-l

--
http://www.freelists.org/webpage/oracle-l

Received on Wed Feb 02 2005 - 09:48:40 CST