Go to the FreeLists Home Page Home Signup Help Login 		 



[oracle-l] || [Date Prev] [05-2006 Date Index] [Date Next] || [Thread Prev] [05-2006 Thread Index] [Thread Next]

Re: *Measuring sql performance (elapsed time and scalability) by number of logical reads

  • From: "Radoulov, Dimitre" <cichomitiko@xxxxxxxxx>
  • To: "Morten Egan" <meg@xxxxxxxxxxxx>, "Bernard Polarski" <bpolarsk@xxxxxxxxx>
  • Date: Tue, 2 May 2006 14:31:15 +0200
Thanks for the feedback,
I will check the different types of logical IO in oracle.

I'm trying to undestand why I have:

1. Fetch 2 0.26 0.25 0 1725 0 1
2. Fetch 2 0.06 0.05 0 7559 0 1

No waits other than SQL*Net messages from/to client in the trace file:

$ grep WAIT xxx_ora_14318_1.trc
WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 8115716 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 893 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 3 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 7863907 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 6 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 749 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 11038250 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 7 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 813 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 14939203 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 7 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 1466 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 3 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 6715399 p1=1650815232 p2=1 p3=0


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

select *
from (select a. *, rownum r
from (select distinct atp.part_number as codice,
lsc.ds_lunga as descr,
'' as TIPOOPT,
'' as b
from filtro_dati_catalogo fdc,
an_telai ati,
vp_tavole vpt,
assoc_tavole_parts atp,
an_parts ap,
lessico_pn lsc
where fdc.id_subcatalogo in (0) and ati.targa = 'FNZ8243' and
lsc.language_code = 1 and
fdc.pv_code = ati.pv_code and
fdc.pv_code = vpt.pv_code and
vpt.cod_tavola_grafica =
atp.cod_tavola_grafica and
ap.part_number = atp.part_number and
lsc.codice_lessico = ap.codice_lessico and
(lsc.ds_lunga like '1118647' or
Trim(ap.part_number) like '1118647')
order by codice asc) a
where rownum <= 23) b
where r > 0

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.09 0.08 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.26 0.25 0 1725 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.35 0.33 0 1725 0 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 26

Rows Row Source Operation
------- ---------------------------------------------------
1 VIEW (cr=1725 r=0 w=0 time=252518 us)
1 COUNT STOPKEY (cr=1725 r=0 w=0 time=252486 us)
1 VIEW (cr=1725 r=0 w=0 time=252477 us)
1 SORT UNIQUE STOPKEY (cr=1725 r=0 w=0 time=252457 us)
1 HASH JOIN (cr=1725 r=0 w=0 time=252287 us)
2535 INDEX FAST FULL SCAN XIF01LESSICO_PN (cr=202 r=0 w=0 time=13998 us)(object id 6850)
3309 HASH JOIN (cr=1523 r=0 w=0 time=223005 us)
3309 NESTED LOOPS (cr=913 r=0 w=0 time=10605 us)
434 NESTED LOOPS (cr=13 r=0 w=0 time=883 us)
1 NESTED LOOPS (cr=7 r=0 w=0 time=155 us)
1 TABLE ACCESS BY INDEX ROWID AN_TELAI (cr=4 r=0 w=0 time=103 us)
1 INDEX RANGE SCAN XIF04AN_TELAI (cr=3 r=0 w=0 time=75 us)(object id 6771)
1 INDEX RANGE SCAN XIF02FILTRO_DATI_CATALOGO (cr=3 r=0 w=0 time=40 us)(object id 6818)
434 INDEX RANGE SCAN PK_VP_TAVOLE (cr=6 r=0 w=0 time=569 us)(object id 13282)
3309 INDEX RANGE SCAN XPKASSOC_TAVOLE_PARTS (cr=900 r=0 w=0 time=7879 us)(object id 6778)
168826 INDEX FAST FULL SCAN XPKAN_PARTS (cr=610 r=0 w=0 time=72513 us)(object id 6761)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 7.86 7.86
********************************************************************************

select *
from (select a. *, rownum r
from (select /*+ USE_NL(lsc ap) */ distinct atp.part_number as codice,
lsc.ds_lunga as descr,
'' as TIPOOPT,
'' as b
from filtro_dati_catalogo fdc,
an_telai ati,
vp_tavole vpt,
assoc_tavole_parts atp,
an_parts ap,
lessico_pn lsc
where fdc.id_subcatalogo in (0) and ati.targa = 'FNZ8243' and
lsc.language_code = 1 and
fdc.pv_code = ati.pv_code and
fdc.pv_code = vpt.pv_code and
vpt.cod_tavola_grafica =
atp.cod_tavola_grafica and
ap.part_number = atp.part_number and
lsc.codice_lessico = ap.codice_lessico and
(lsc.ds_lunga like '1118647' or
Trim(ap.part_number) like '1118647')
order by codice asc) a
where rownum <= 23) b
where r > 0

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.23 0.22 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.06 0.05 0 7559 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.29 0.28 0 7559 0 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 26

Rows Row Source Operation
------- ---------------------------------------------------
1 VIEW (cr=7559 r=0 w=0 time=59446 us)
1 COUNT STOPKEY (cr=7559 r=0 w=0 time=59427 us)
1 VIEW (cr=7559 r=0 w=0 time=59419 us)
1 SORT UNIQUE STOPKEY (cr=7559 r=0 w=0 time=59408 us)
1 CONCATENATION (cr=7559 r=0 w=0 time=59300 us)
1 TABLE ACCESS BY INDEX ROWID LESSICO_PN (cr=7550 r=0 w=0 time=59147 us)
3 NESTED LOOPS (cr=7549 r=0 w=0 time=59117 us)
1 NESTED LOOPS (cr=7547 r=0 w=0 time=59076 us)
3309 NESTED LOOPS (cr=913 r=0 w=0 time=12427 us)
434 NESTED LOOPS (cr=13 r=0 w=0 time=986 us)
1 NESTED LOOPS (cr=7 r=0 w=0 time=168 us)
1 TABLE ACCESS BY INDEX ROWID AN_TELAI (cr=4 r=0 w=0 time=117 us)
1 INDEX RANGE SCAN XIF04AN_TELAI (cr=3 r=0 w=0 time=83 us)(object id 6771)
1 INDEX RANGE SCAN XIF02FILTRO_DATI_CATALOGO (cr=3 r=0 w=0 time=43 us)(object id 6818)
434 INDEX RANGE SCAN PK_VP_TAVOLE (cr=6 r=0 w=0 time=640 us)(object id 13282)
3309 INDEX RANGE SCAN XPKASSOC_TAVOLE_PARTS (cr=900 r=0 w=0 time=9297 us)(object id 6778)
1 INDEX RANGE SCAN XPKAN_PARTS (cr=6634 r=0 w=0 time=40841 us)(object id 6761)
1 INDEX RANGE SCAN XPKLESSICO_PN (cr=2 r=0 w=0 time=29 us)(object id 6851)
0 NESTED LOOPS (cr=9 r=0 w=0 time=107 us)
0 NESTED LOOPS (cr=9 r=0 w=0 time=107 us)
0 NESTED LOOPS (cr=9 r=0 w=0 time=106 us)
0 NESTED LOOPS (cr=9 r=0 w=0 time=105 us)
1 NESTED LOOPS (cr=7 r=0 w=0 time=77 us)
1 TABLE ACCESS BY INDEX ROWID AN_TELAI (cr=4 r=0 w=0 time=42 us)
1 INDEX RANGE SCAN XIF04AN_TELAI (cr=3 r=0 w=0 time=27 us)(object id 6771)
1 INDEX RANGE SCAN XIF02FILTRO_DATI_CATALOGO (cr=3 r=0 w=0 time=26 us)(object id 6818)
0 INDEX RANGE SCAN XIF01LESSICO_PN (cr=2 r=0 w=0 time=21 us)(object id 6850)
0 INDEX RANGE SCAN XIF01AN_PARTS (cr=0 r=0 w=0 time=0 us)(object id 6760)
0 INDEX RANGE SCAN XIF01ASSOC_TAVOLE_PARTS (cr=0 r=0 w=0 time=0 us)(object id 6777)
0 INDEX RANGE SCAN PK_VP_TAVOLE (cr=0 r=0 w=0 time=0 us)(object id 13282)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 11.03 11.03
********************************************************************************


Regards,
Dimitre

P.S. Don't ask why the hint includes both tables, with /*+ USE_NL(lsc) */, /*+ USE_NL(ap) */ the plan is different.


----- Original Message ----- From: "Morten Egan" <meg@xxxxxxxxxxxx>
To: <cichomitiko@xxxxxxxxx>; "Bernard Polarski" <bpolarsk@xxxxxxxxx>
Cc: <oracle-l@xxxxxxxxxxxxx>
Sent: Tuesday, May 02, 2006 2:18 PM
Subject: Re: *Measuring sql performance (elapsed time and scalability) by number of logical reads


A logical IO is not a logical IO :)

There are many diff. types of logical IO in oracle, and many of them involve completely different code paths, taking diff. amounts of time to complete.

Regards,
Morten Egan
-----Original message-----
From: "Radoulov, Dimitre" cichomitiko@xxxxxxxxx
Date: Tue, 2 May 2006 14:08:53 +0200
To: "Bernard Polarski" bpolarsk@xxxxxxxxx
Subject: Re: *Measuring sql performance (elapsed time and scalability) by number of logical reads

>I think you have been a bit short in the problem description.
>
> You just meant that all the requested data is already in buffer and no
> physical read is needed.
> Thanks but we have no information on the nature of the sql, the amount > of
> data, the expected goal.
> Bad or good SQL is a ratio of these. What if I read one million blocks
> from my multi gig db block buffer
> to return a tiny rowset for the worse ever seen SQL, it will satisfy > your
> prerequisite and still be very bad.

Excuse me for not being clear, I meant, theoretically speaking:

SQL 1 reads n1 blocks from buffer (no physical read) to complete, elapsed
time t1
SQL 2 reads n2 (where n2 > n1) blocks from buffer (no physical read) to
complete, elapsed time t2

t1 is greater than t2

Always theoretically/hypothetical speaking:
could anyone comment the possibile reasons behind such behaviour.



Regards,
Dimitre



--
http://www.freelists.org/webpage/oracle-l




--
http://www.freelists.org/webpage/oracle-l



[ Home | Signup | Help | Login | Archives | Lists ]

All trademarks and copyrights within the FreeLists archives are owned by their respective owners.
Everything else ©2007 Avenir Technologies, LLC.