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