Interpreting TKPROF output
631280Aug 26 2008 — edited Aug 29 2008Hello colleagues
Im reviewing the performance of one of our DBs (10.2.0.2 on MS 2003 SP1). I found a lookup table called ACCESS_INAB which was called frequently. Pinning this table to the keep buffer we improved the owerall reaction time of the application.
There is still one issue Im fighting with. One specific operation takes still long time (30-45 sec.) to display a comment field. I tried to trace the session and got follwoing result:
********************************************************************************
select *
from
(select rownum rn, a.* from ( SELECT TL.id, TL.process_id, TL.event_time,
TL.severity, TL.short_description, TPG.process_group_text, TP.process_text,
u.display_user_name FROM Transaction_Log TL, Transaction_Process_Groups TPG,
Transaction_Process TP, users u WHERE TP.process_group_id =
TPG.process_group_id and TL.process_id = TP.process_id and TL.pguid =
u.pguid (+) ORDER BY severity desc, event_time) a ) where rn between 1 and
10
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 5.09 73.06 60248 47768 55 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 5.09 73.07 60248 47768 55 10
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 45
Rows Row Source Operation
------- ---------------------------------------------------
10 VIEW (cr=47768 pr=60248 pw=14888 time=62516706 us)
582169 COUNT (cr=47768 pr=60248 pw=14888 time=91625035 us)
582169 VIEW (cr=47768 pr=60248 pw=14888 time=91042864 us)
582169 SORT ORDER BY (cr=47768 pr=60248 pw=14888 time=90460690 us)
582169 HASH JOIN (cr=47768 pr=52211 pw=6851 time=92165669 us)
8 TABLE ACCESS FULL TRANSACTION_PROCESS_GROUPS (cr=7 pr=0 pw=0 time=52 us)
582169 HASH JOIN (cr=47761 pr=52211 pw=6851 time=91000485 us)
62 TABLE ACCESS FULL TRANSACTION_PROCESS (cr=7 pr=0 pw=0 time=86 us)
582169 HASH JOIN RIGHT OUTER (cr=47754 pr=52211 pw=6851 time=89252852 us)
618316 MAT_VIEW ACCESS FULL ACCESS_INAB (cr=12656 pr=10308 pw=0 time=21098797 us)
582169 TABLE ACCESS FULL TRANSACTION_LOG (cr=35098 pr=35052 pw=0 time=28542620 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file scattered read 3808 0.26 41.01
db file sequential read 361 0.15 1.78
direct path write temp 616 0.10 2.09
direct path read temp 2023 0.34 13.95
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.01 0.01
********************************************************************************
Can you help me to correctly interpret this outcome?
Kind regards
Tony
PS: I used [this |http://download.oracle.com/docs/cd/B19306_01/server.102/b14211/instance_tune.htm#i34268] reference.
Edited by: TonyDBA on Aug 26, 2008 2:19 AM