| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Re: Tkprof result reading
In article <bd9a9a76.0106260807.1ab498ed_at_posting.google.com>, bchorng_at_yahoo.com
says...
>
>Thomas Kyte <tkyte_at_us.oracle.com> wrote in message
>news:<9h8q7g02cr6_at_drn.newsguy.com>...
>>In article <bd9a9a76.0106251145.76ff5220_at_posting.google.com>, bchorng_at_yahoo.com
>:
>: < lines deleted>
>:
>>
>>so, in my case, it means I was doing a select for update on an unindexed table
>> -- the execute phase had to do it 100 times, the fetch phase once.
>>
>>
>> Are you doing something similar?
>>
>
>Thomas, this SQL is a pure select. I did not write it, it came from
>our
>application. Here is the complete information:
>
>********************************************************************************
>
>SELECT COUNT(*)
>FROM
> SPDUAL WHERE EXISTS (SELECT R.ID FROM ROLEPRIVILEGE
>RP,ROLEMEMBERSHIP RM,
> ROLE R WHERE RM.PERSON_ID = :b1 AND R.ENTITY_TYPE = 'G' AND R.ID
>=
> RM.ROLE_ID AND RP.RESTRICTION_ID = 1 AND RM.ROLE_ID = RP.ROLE_ID
>AND
> RP.PRIVILEGE_ID = :b2 )
>
This is much better - the query, the version, the OS..., ok, apparently, much of the work of the EXISTS is being counted in the EXECUTE phase of the query. Consider this small example:
ops$tkyte_at_ORA817.US.ORACLE.COM> create table spdual as select * from dual; Table created.
ops$tkyte_at_ORA817.US.ORACLE.COM> create table t1 as select rownum r, rpad('*',3000,'*') data from all_objects where rownum <= 20;
Table created.
On my system (8k blocks) that created a 10 block table. Now I run a block of code:
ops$tkyte_at_ORA817.US.ORACLE.COM> declare
2 l_cnt number;
3 begin
4 for i in 1 .. 3003 5 loop 6 select count(*) into l_cnt 7 from spdual Test_1 8 where exists ( select NULL from t1 where r = (i-2990) ); 9 end loop;
PL/SQL procedure successfully completed.
The TKPROF for that query shows:
SELECT COUNT(*)
FROM
SPDUAL TEST_1 WHERE EXISTS (SELECT NULL FROM T1 WHERE R = (:b1 - 2990
) )
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0 Execute 3003 1.09 1.00 10 41961 36036 0 Fetch 3003 0.05 0.03 1 65 156 3003 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6007 1.14 1.03 11 42026 36192 3003
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 334 (OPS$TKYTE) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
3003 SORT AGGREGATE
13 FILTER
13 TABLE ACCESS FULL SPDUAL
ops$tkyte_at_ORA817.US.ORACLE.COM> create index t1_idx on t1(r); Index created.
ops$tkyte_at_ORA817.US.ORACLE.COM> declare
2 l_cnt number;
3 begin
4 for i in 1 .. 3003 5 loop 6 select count(*) into l_cnt 7 from spdual Test_2 8 where exists ( select NULL from t1 where r = (i-2990) ); 9 end loop;
PL/SQL procedure successfully completed.
SELECT COUNT(*)
FROM
SPDUAL TEST_2 WHERE EXISTS (SELECT NULL FROM T1 WHERE R = (:b1 - 2990
) )
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0 Execute 3003 0.35 0.41 0 3003 0 0 Fetch 3003 0.04 0.06 0 65 156 3003 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6007 0.39 0.47 0 3068 156 3003
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 334 (OPS$TKYTE) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
3003 SORT AGGREGATE
13 FILTER
13 TABLE ACCESS FULL SPDUAL
We can see the work during the execute when wwaaayyy down. the execute phase was counting the work done by the where exists.
Now, to analyze your results:
>
>call count cpu elapsed disk query current rows
>------- ------ ------ ------- ---------- ---------- ---------- ----------
>Parse 1 0.02 0.00 0 0 0 0
>Execute 3003 0.88 0.70 3 30030 0 0
>Fetch 3003 0.13 0.20 2 3003 12012 3003
>------- ------ ------ ------- ---------- ---------- ---------- ----------
>total 6007 1.03 0.90 5 33033 12012 3003
That says we process 30030 logical I/Os (average of 10 blocks per query) in the WHERE EXISTS you have.
The Fetch phase has 12012 current mode reads -- thats to perform the full scan of SPDUAL (looks like your where exists was satisified each and every time, 12012/3003 = 4 and in 817 i would expect 4 current mode reads).
The fetch phase has 3003 query mode gets, your spdual table must be 1 block big.
>
>Misses in library cache during parse: 1
>Optimizer goal: CHOOSE
>Parsing user id: 245 (TRAIN_ENCORE) (recursive depth: 1)
>
>Rows Execution Plan
>------- ---------------------------------------------------
> 0 SELECT STATEMENT GOAL: CHOOSE
> 0 SORT (AGGREGATE)
> 0 FILTER
> 0 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'SPDUAL'
> 0 NESTED LOOPS
> 0 NESTED LOOPS
> 0 INDEX GOAL: ANALYZED (RANGE SCAN) OF
> 'PK_ROLEMEMBERSHIP' (UNIQUE)
> 0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'ROLE'
> 0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
> 'SYS_C00215078' (UNIQUE)
> 0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'ROLEPRIVILEGE'
> 0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
> 'PK_ROLEPRIVILEGE' (UNIQUE)
>
>********************************************************************************
>
>Another question I have is, why are the rows column all 0 in explain
>plan ? I exited out of the application before tkprofing.
>
that, i cannot answer -- as you can see with mine (also 817 on solaris) they were there. These numbers get recorded when the cursor itself is closed. I think that the process that ran this query did not exit "all of the way" - perhaps there is a middle tier involved?
>By the way, this is 8.1.7 on Solaris 2.7
>
>Thanks.
>
>-Bass Chorng
-- Thomas Kyte (tkyte@us.oracle.com) http://asktom.oracle.com/ Expert one on one Oracle, programming techniques and solutions for Oracle. http://www.amazon.com/exec/obidos/ASIN/1861004826/ Opinions are mine and do not necessarily reflect those of Oracle CorpReceived on Tue Jun 26 2001 - 12:14:08 CDT
 |
 |