Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Mailing Lists -> Oracle-L -> RE: cpu time and query column in tkprof output

RE: cpu time and query column in tkprof output

From: Yasin Baskan <yasbs_at_kocbank.com.tr>
Date: Wed, 2 Feb 2005 15:54:32 +0200
Message-ID: <083667B535F3464CA0DD0D1DAFA4E37604D50AF0@camexc1.kfs.local> 





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]=20
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 =3D usually more elapsed time.
More sorts or more complex memory operations =3D 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





> Hi,
> =20




>=20


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




>=20


> =20




>=20


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




>=20


> How should i comment on the following output?




>=20


> =20




>=20


> =20




>=20


> SELECT COUNT (*)




>=20


>   FROM faxutil.t_kfs_jobs j, faxutil.t_kfs_actions a




>=20


>  WHERE j.NO =3D a.jobno




>=20


>    AND a.pool_id =3D :poolname




>=20


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


>=20

>                                       FROM
> faxutil.t_kfs_actions


>=20

>                                      WHERE pool_id =3D
> :poolname


>=20

>                                   GROUP BY jobno)




>=20


>    AND EXISTS (


>=20

>           SELECT pool_status, job_status


>=20

>             FROM faxutil.t_kfs_tabstatuses


>=20

>            WHERE tabno =3D :ptabno


>=20

>              AND pool_status =3D a.status


>=20

>              AND job_status =3D j.status)




>=20


> =20


>=20

> call     count       cpu    elapsed       disk    =20
> query    current
> rows




>=20


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


>=20

> Parse        1      0.00       0.00          0     =20
>    0          0
> 0


>=20

> Execute      2      0.00       0.00          0     =20
>    0          0
> 0


>=20

> Fetch        2      0.18       0.31         14    =20
> 11677         58
> 1




>=20


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


>=20

> total        5      0.18       0.31         14    =20
> 11677         58
> 1




>=20


> =20




>=20


> Misses in library cache during parse: 0




>=20


> Optimizer goal: CHOOSE




>=20


> =20




>=20


> Misses in library cache during parse: 0




>=20


> Optimizer goal: CHOOSE




>=20


> Parsing user id: 46




>=20


> =20


>=20

> Rows     Row Source Operation




>=20


> -------=20
> ---------------------------------------------------


>=20

>       1  SORT AGGREGATE


>=20

>      14   FILTER




>=20


>    2768    NESTED LOOPS


>=20

>    2768     HASH JOIN


>=20

>    2767      VIEW VW_NSO_1


>=20

>    2767       SORT GROUP BY


>=20

>    2875        INDEX RANGE SCAN (object id 34317)


>=20

>    2875      INDEX RANGE SCAN (object id 34317)


>=20

>    5534     TABLE ACCESS BY INDEX ROWID T_KFS_JOBS


>=20

>    5534      INDEX UNIQUE SCAN (object id 31338)


>=20

>      14    TABLE ACCESS FULL T_KFS_TABSTATUSES




>=20


> =20




>=20


> =20




>=20


> select /*+ ordered */




>=20


>   count(*)




>=20


>  from




>=20


>   faxutil.t_kfs_tabstatuses c,




>=20


>   faxutil.t_kfs_jobs j,




>=20


>   faxutil.t_kfs_actions a,




>=20


>   ( select jobno, max(iteration) iteration




>=20


>   from faxutil.t_kfs_actions




>=20


>   where pool_id =3D :poolname




>=20


>   group by jobno ) sqry1




>=20


>  where




>=20


>   j.no =3D a.jobno




>=20


>   and a.pool_id =3D :poolname




>=20


>   and a.jobno =3D sqry1.jobno




>=20


>   and a.iteration =3D sqry1.iteration




>=20


>  and c.tabno =3D :ptabno




>=20


>  and c.pool_status =3D a.status




>=20


>  and c.job_status =3D j.status




>=20


> =20


>=20

> call     count       cpu    elapsed       disk    =20
> query    current
> rows




>=20


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


>=20

> Parse        1      0.00       0.00          0     =20
>    0          0
> 0


>=20

> Execute      2      0.00       0.00          0     =20
>    0          0
> 0


>=20

> Fetch        2      0.82       1.44         31     =20
> 4565         58
> 1




>=20


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


>=20

> total        5      0.82       1.44         31     =20
> 4565         58
> 1




>=20



=3D=3D=3D message truncated =3D=3D=3D





        =09

__________________________________=20




Do you Yahoo!?=20


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

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


Received on Wed Feb 02 2005 - 08:59:25 CST












Original text of this message













  HOME |
  ASK QUESTION |
  ADD INFO |
  SEARCH |
  E-MAIL US