Unix Technical Forum

Help on understanding TKprof

This is a discussion on Help on understanding TKprof within the Oracle Database forums, part of the Database Server Software category; --> i have this query, and i can notice that logical reads are by far larger that phisical ones, yet, ...


Go Back   Unix Technical Forum > Database Server Software > Oracle Database

Register FAQ Members List Calendar Search Today's Posts Mark Forums Read
  #1 (permalink)  
Old 02-25-2008, 01:29 AM
Melgar
 
Posts: n/a
Default Help on understanding TKprof

i have this query,
and i can notice that logical reads are by far larger that phisical
ones, yet, the rows retrived are few.
Since the quere seems to be taking an acceptable execution plan (to me
at least)

where can i start to find out whats going on?

Thx in advance.

select R.NIS_RAD ,R.SEC_NIS ,R.SEC_REC ,R.F_FACT ,R.COD_CLI ,R.SEC_CTA
,
R.IMP_TOT_REC ,R.EST_ACT ,R.F_VCTO_FAC ,R.COD_UNICOM ,R.NUM_DIAS_REC
,
NVL(REPLACE(R.COD_TAR,' '),' ') ,R.TIP_REC ,R.IMP_CTA ,R.TIP_CLI ,
R.IND_GESTION_CUENTA ,R.SIMBOLO_VAR ,R.NUM_IDENT_SIPO
,R.IND_CONVERSION
from
RECIBOS R where (((R.NIS_RAD=:b0 and ((R.SEC_NIS=:b1 or (R.SEC_NIS<:b1
and
R.IND_TRASPASO=1)) or exists (select 1 from CUOTAS_PL P ,MACUERDOS M
where
(((((((P.NIS_RAD=R.NIS_RAD and P.SEC_NIS=R.SEC_NIS) and
P.F_FACT=R.F_FACT)
and P.SEC_REC=R.SEC_REC) and M.NIS_RAD=P.NIS_RAD) and
M.NUM_ACU=P.NUM_ACU)
and P.SEC_NIS<:b1) and M.IND_TRASPASO=1)))) and R.EST_ACT in (select
EST_REC from GRUPO_EST where (CO_GRUPO=:b4 and EST_REC=R.EST_ACT)))
and
(((R.F_FACT<TO_DATE(:b5,'YYYYMMDD') and R.TIP_REC not in
('TR090','TR013',
'TR091','TR092')) or (R.F_FACT=TO_DATE(:b5,'YYYYMMDD') and
R.SEC_REC<=:b7))
or (R.F_FACT=TO_DATE(:b5,'YYYYMMDD') and R.TIP_REC in
('TR030','TR092',
'TR091','TR032')))) order by F_FACT,SEC_REC desc

sumarized for you:

Disk reads : 39474
Query : 1491555
rows Retrived: 4175

call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 8 0.00 0.00 0 0 0
0
Execute 3921 4.50 4.49 0 0 0
0
Fetch 8097 51.37 1024.32 139474 1491555 0
4175
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 12026 55.87 1028.81 139474 1491555 0
4175

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 256 (BATCH)

Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
487 SORT (ORDER BY)
0 CONCATENATION
0 NESTED LOOPS
0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'RECIBOS'
30846 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'PK_RECIBOS_NEW'
(UNIQUE)
0 NESTED LOOPS
0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'CUOTAS_PL'
60798 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'CUOTAS_PL_I03' (NON-UNIQUE)
0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'MACUERDOS'
0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'PK_MACUERDOS' (UNIQUE)
0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_GRUPO_EST'
(UNIQUE)
0 NESTED LOOPS
135 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'RECIBOS'
615 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'PK_RECIBOS_NEW'
(UNIQUE)
0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_GRUPO_EST'
(UNIQUE)
453 NESTED LOOPS
30231 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'RECIBOS'
30711 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'PK_RECIBOS_NEW'
(UNIQUE)
29840 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_GRUPO_EST'
(UNIQUE)

************************************************** ******************************

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #2 (permalink)  
Old 02-25-2008, 01:29 AM
Jonathan Lewis
 
Posts: n/a
Default Re: Help on understanding TKprof


"Melgar" <luis_melgar@yahoo.com> wrote in message
news:1136584876.038803.114390@g49g2000cwa.googlegr oups.com...
>i have this query,
> and i can notice that logical reads are by far larger that phisical
> ones, yet, the rows retrived are few.
> Since the quere seems to be taking an acceptable execution plan (to me
> at least)
>
> where can i start to find out whats going on?
>
> Thx in advance.
>
> select R.NIS_RAD ,R.SEC_NIS ,R.SEC_REC ,R.F_FACT ,R.COD_CLI ,R.SEC_CTA
> from
> RECIBOS R where (((R.NIS_RAD=:b0 and ((R.SEC_NIS=:b1 or (R.SEC_NIS<:b1
> and
> R.IND_TRASPASO=1)) or exists (select 1 from CUOTAS_PL P ,MACUERDOS M
> where
> (((((((P.NIS_RAD=R.NIS_RAD and P.SEC_NIS=R.SEC_NIS) and
> P.F_FACT=R.F_FACT)
> and P.SEC_REC=R.SEC_REC) and M.NIS_RAD=P.NIS_RAD) and
> M.NUM_ACU=P.NUM_ACU)
> and P.SEC_NIS<:b1) and M.IND_TRASPASO=1)))) and R.EST_ACT in (select
> EST_REC from GRUPO_EST where (CO_GRUPO=:b4 and EST_REC=R.EST_ACT)))
> and
> (((R.F_FACT<TO_DATE(:b5,'YYYYMMDD') and R.TIP_REC not in
> ('TR090','TR013',
> 'TR091','TR092')) or (R.F_FACT=TO_DATE(:b5,'YYYYMMDD') and
> R.SEC_REC<=:b7))
> or (R.F_FACT=TO_DATE(:b5,'YYYYMMDD') and R.TIP_REC in
> ('TR030','TR092',
> 'TR091','TR032')))) order by F_FACT,SEC_REC desc
>
> Rows Execution Plan
> ------- ---------------------------------------------------
> 0 SELECT STATEMENT GOAL: CHOOSE
> 487 SORT (ORDER BY)
> 0 CONCATENATION
> 0 NESTED LOOPS
> 0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'RECIBOS'
> 30846 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'PK_RECIBOS_NEW'
> (UNIQUE)
> 0 NESTED LOOPS
> 0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'CUOTAS_PL'
> 60798 INDEX GOAL: ANALYZED (RANGE SCAN) OF
> 'CUOTAS_PL_I03' (NON-UNIQUE)
> 0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'MACUERDOS'
> 0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
> 'PK_MACUERDOS' (UNIQUE)
> 0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_GRUPO_EST'
> (UNIQUE)
> 0 NESTED LOOPS
> 135 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'RECIBOS'
> 615 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'PK_RECIBOS_NEW'
> (UNIQUE)
> 0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_GRUPO_EST'
> (UNIQUE)
> 453 NESTED LOOPS
> 30231 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'RECIBOS'
> 30711 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'PK_RECIBOS_NEW'
> (UNIQUE)
> 29840 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_GRUPO_EST'
> (UNIQUE)
>
> ************************************************** ******************************
>



This execution plan is almost certainly NOT what is
actually happening. It has been produced by the
'explain = ' option of tkprof, not formatted from the
STAT# lines in the trace file that usually get dumped
when the cursor closes.

Reasons for it being the wrong plan - the SQL has
some bind variables in it so Oracle has no information
about the bind types, and may be making the wrong
assumptions; also, you have predicates with ranges
in them R.SEC_REC<=:b7, P.SEC_NIS<:b1, which
means that Oracle will be using 5% for the selectivities
when using explain plan, whereas it might have peeked
to get better information at run-time (assuming you are
using 9i or better).


Next step - get the hash_value from the trace file (hv=)
from the PARSING IN CURSOR line, and use it to
extract the run-time plan from v$sql_plan (assuming
again that you are on 9i or better).

--
Regards

Jonathan Lewis

http://www.jlcomp.demon.co.uk/faq/ind_faq.html
The Co-operative Oracle Users' FAQ

http://www.jlcomp.demon.co.uk/cbo_book/ind_book.html
Cost Based Oracle: Fundamentals

http://www.jlcomp.demon.co.uk/appearances.html
Public Appearances - schedule updated 29th Nov 2005


Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #3 (permalink)  
Old 02-25-2008, 01:29 AM
Melgar
 
Posts: n/a
Default Re: Help on understanding TKprof

smon timer - SMON waiting for work

excuse me.. its usless information >.<

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #4 (permalink)  
Old 02-25-2008, 01:29 AM
Melgar
 
Posts: n/a
Default Re: Help on understanding TKprof

my bad, it is oracle database ver. 8.0.5

>.<


ill check up your advice thx

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #5 (permalink)  
Old 02-25-2008, 01:29 AM
Melgar
 
Posts: n/a
Default Re: Help on understanding TKprof

on the other hand i had run a utlstats report and i notice that rdbms
ipc message avg time its huge.

what rdbms ipc message means?

Event Name Count Total Time Avg Time

-------------------------------- ------------- -------------
-------------
SQL*Net message from client 736119 7846568
10.66
rdbms ipc message 182 1068142
5868.91
db file sequential read 850280 774935
..91
pipe get 1094 529888
484.36

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #6 (permalink)  
Old 02-25-2008, 01:29 AM
Melgar
 
Posts: n/a
Default Re: Help on understanding TKprof

ive just noticed that

Event Name Count Total Time Avg Time

-------------------------------- ------------- -------------
-------------
rdbms ipc message 42879 2613171
60.94
slave wait 34699 2045894
58.96
pmon timer 1761 529830
300.87
smon timer 17 509963
29997.82

smon timer is somehow related to the rdbms ipc message from my last
reply.

the time- window for this utlstat is 50 min

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #7 (permalink)  
Old 02-25-2008, 01:29 AM
Sybrand Bakker
 
Posts: n/a
Default Re: Help on understanding TKprof

On 6 Jan 2006 14:35:49 -0800, "Melgar" <luis_melgar@yahoo.com> wrote:

>on the other hand i had run a utlstats report and i notice that rdbms
>ipc message avg time its huge.
>
>what rdbms ipc message means?
>
>Event Name Count Total Time Avg Time
>
>-------------------------------- ------------- -------------
>-------------
>SQL*Net message from client 736119 7846568
>10.66
>rdbms ipc message 182 1068142
>5868.91
>db file sequential read 850280 774935
>.91
>pipe get 1094 529888
>484.36


ipc = interprocess communication
rdbms ipc : communication between the various Oracle related
processes.
Oracle considers this to be an idle event which is irrelevant for any
tuning.

--
Sybrand Bakker, Senior Oracle DBA
Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #8 (permalink)  
Old 02-25-2008, 01:30 AM
Melgar
 
Posts: n/a
Default Re: Help on understanding TKprof

This execution plan is almost certainly NOT what is
actually happening......

I cant express how much i thank you Jonathan ...

You give me the light i just need.

it happen that this particular instance has the defaults values of
OPTIMIZER_INDEX_CACHING and OPTIMIZER_INDEX_COST_ADJ

stated that, the performance has increased in 40% at least.

: )

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
Reply


Thread Tools
Display Modes

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

vB code is On
Smilies are On
[IMG] code is On
HTML code is Off
Trackbacks are On
Pingbacks are On
Refbacks are On
Forum Jump


All times are GMT. The time now is 09:50 AM.


Powered by vBulletin® Version 3.6.5
Copyright ©2000 - 2008, Jelsoft Enterprises Ltd.
SEO by vBSEO 3.2.0
www.UnixAdminTalk.com