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, ...
| |||||||
| Register | FAQ | Members List | Calendar | Search | Today's Posts | Mark Forums Read |
| ||||
| 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) ************************************************** ****************************** |
| |||
| "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 |
| |||
| 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 |
| |||
| 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 |
| |||
| 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 |
| ||||
| 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. : ) |