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: Thu, 3 Feb 2005 10:30:45 +0200
Message-ID: <083667B535F3464CA0DD0D1DAFA4E37604D8695E@camexc1.kfs.local> 





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_at_freelists.org


[mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Cary Millsap
Sent: Wednesday, February 02, 2005 4:45 PM
To: oracle-l_at_freelists.org


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






-----Original Message-----



From: oracle-l-bounce_at_freelists.org =3D


[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]=3D3D20
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 =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





> 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


--



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



--



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


--



http://www.freelists.org/webpage/oracle-l
Received on Thu Feb 03 2005 - 03:33:05 CST












Original text of this message













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