| 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: Help with sql query speed. Explain plan included
On Mar 21, 3:42 pm, Maxim Demenko <mdeme..._at_gmail.com> wrote:
> Charles Hooper schrieb:
>
> > On Mar 18, 11:11 pm, "fitzjarr..._at_cox.net" <fitzjarr..._at_cox.net>
> > wrote:
> > Your results
> > may vary on other platforms.
>
> > Charles Hooper
> > PC Support Specialist
> > K&M Machine-Fabricating, Inc.
>
> Some thoughts (Charles, sorry, i snipped your results, because my
> posting came out too to long, but i'll reference sometimes execution
> plans which you have posted):
> Abgelaufen: 00:00:00.05
> SQL> select * from table(dbms_xplan.display);
>
> PLAN_TABLE_OUTPUT
> -----------------------------------------------------------------------------------------------------------------------------
> Plan hash value: 2982241237
>
> ---------------------------------------------------------------------------------------------------------
> | Id | Operation | Name | Rows | Bytes
> |TempSpc| Cost (%CPU)| Time |
> ---------------------------------------------------------------------------------------------------------
> | 0 | SELECT STATEMENT | | 42549 |
> 914K| | 3646 (2)| 00:00:44 |
> |* 1 | FILTER | | |
> | | | |
> | 2 | HASH GROUP BY | | 42549 |
> 914K| 27M| 3646 (2)| 00:00:44 |
> | 3 | NESTED LOOPS | | 850K|
> 17M| | 1434 (1)| 00:00:18 |
> | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 51 | 561
> | | 56 (0)| 00:00:01 |
> |* 5 | INDEX RANGE SCAN | T1_IDX | 51 |
> | | 4 (0)| 00:00:01 |
> |* 6 | TABLE ACCESS CLUSTER | T1 | 16550 |
> 177K| | 27 (0)| 00:00:01 |
> |* 7 | INDEX UNIQUE SCAN | T1_CLUSTER_IDX | 1 |
> | | 0 (0)| 00:00:01 |
> ---------------------------------------------------------------------------------------------------------
>
> Predicate Information (identified by operation id):
> ---------------------------------------------------
>
> 1 - filter(COUNT(*)>10)
> 5 - access("T0"."RESIDENTID"=1486674)
> 6 - filter("T0"."RESIDENTID"<>"TX"."RESIDENTID" AND
> "TX"."RESIDENTID"<>1486674)
> 7 - access("T0"."QUESTIONNUMBER"="TX"."QUESTIONNUMBER" AND
> "T0"."ANSWER"="TX"."ANSWER")
>
> Best regards
>
> Maxim
I will take a closer look at what you posted later.
I have lost confidence in the timings that I posted in this thread.
The timings were pulled directly from 10053 trace files. In a thread
on C.D.O.M. I posted that I was seeing odd differences in the timings
between 10053 trace files and the stat lines in 10046 trace files.
The first time I collected system statistics for this database, there
was little activity in the database during the full system statistics
run:
EXEC DBMS_STATS.GATHER_SYSTEM_STATS('interval', interval => 30)
At the end of statistics calculations:
SELECT
SNAME,
PNAME,
PVAL1
FROM
SYS.AUX_STATS;
SNAME PNAME
------------------------------ ------------------------------ ---------- SYSSTATS_INFO STATUS SYSSTATS_INFO DSTART SYSSTATS_INFO DSTOP SYSSTATS_INFO FLAGS 0 SYSSTATS_MAIN CPUSPEEDNW 762.300459 SYSSTATS_MAIN IOSEEKTIM 10 SYSSTATS_MAIN IOTFRSPEED 4096 SYSSTATS_MAIN SREADTIM 15.294 SYSSTATS_MAIN MREADTIM 80.556 SYSSTATS_MAIN CPUSPEED 756 SYSSTATS_MAIN MBRC 14 SYSSTATS_MAIN MAXTHR SYSSTATS_MAIN SLAVETHR
Some of the timings that I saw in 10053 traces differed by a factor of 10 from the actual timings reported by the STAT lines in 10046 traces. Last night I put the database under a heavy load, and this is how the statistics in SYS.AUX_STATS changed after re-collecting system statistics:
SNAME PNAME
------------------------------ ------------------------------ ---------- SYSSTATS_INFO STATUS SYSSTATS_INFO DSTART SYSSTATS_INFO DSTOP SYSSTATS_INFO FLAGS 0 SYSSTATS_MAIN CPUSPEEDNW 762.300459 SYSSTATS_MAIN IOSEEKTIM 10 SYSSTATS_MAIN IOTFRSPEED 4096 SYSSTATS_MAIN SREADTIM 5.354 SYSSTATS_MAIN MREADTIM 8.534 SYSSTATS_MAIN CPUSPEED 756 SYSSTATS_MAIN MBRC 8 SYSSTATS_MAIN MAXTHR SYSSTATS_MAIN SLAVETHR
Note that the multi-block read time is now 1/10 of the original value. Prior to re-collecting system statistics, these are the timing that I saw for one SQL statement in the other thread: 10053 plan:
+-----------------------------------+ | Id | Operation | Name | Rows | Bytes | Cost | Time | -------------------------------------------- +-----------------------------------+ | 0 | INSERT STATEMENT | | | | 2774 | | | 1 | HASH JOIN RIGHT ANTI | | 1 | 19 | 2774 |00:00:43 |
+-----------------------------------+
10046 STAT lines
CPU Time 4.383628,Elapsed Time 4.450739,Rows Affected 400000,Blks from
Buff 5881+CU(23455),Blks from Disk 0,Goal=ALL_ROWS
(Rows 400000) HASH JOIN RIGHT ANTI (cr=3793 pr=0 pw=0 time=3345121
us)
(Rows 500000) INDEX FAST FULL SCAN SYS_C007848 (cr=2468 pr=0 pw=0
time=1500148 us)
(Rows 500000) TABLE ACCESS FULL TA (cr=1325 pr=0 pw=0
time=1512393 us)
After re-collecting system statistics, the same SQL statement: -------------------------------------------- +-----------------------------------+ | Id | Operation | Name | Rows | Bytes | Cost | Time | -------------------------------------------- +-----------------------------------+ | 0 | INSERT STATEMENT | | | | 1172 | | | 1 | HASH JOIN RIGHT ANTI | | 1 | 19 | 1172 |00:00:07 |
+-----------------------------------+
10046 STAT lines
CPU Time 4.461628,Elapsed Time 4.513300,Rows Affected 400000,Blks from
Buff 5880+CU(23457),Blks from Disk 0,Goal=ALL_ROWS
(Rows 400000) HASH JOIN RIGHT ANTI (cr=3793 pr=0 pw=0 time=3360117
us)
(Rows 500000) INDEX FAST FULL SCAN SYS_C007848 (cr=2468 pr=0 pw=0
time=1500075 us)
(Rows 500000) TABLE ACCESS FULL TA (cr=1325 pr=0 pw=0
time=1511574 us)
The times reported in the 10053 trace are now closer to the times in
the 10046 trace, but still not accurate. How does this apply to this
thread? Let's take the original SQL statement posted in this and
analyze it three ways:
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTF1';
Set up the SQL statement so that DBMS_XPLAN can return a lot of
details about the actual execution:
select /*+ GATHER_PLAN_STATISTICS */
tx.residentid
from t1 t0,t1 tx
where t0.residentid!=tx.residentid
and t0.questionnumber=tx.questionnumber
and t0.answer=tx.answer
and t0.residentid=1486674
group by tx.residentid
having count(*)>10;
SELECT
*
FROM
TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
DBMS_XPLAN:
Plan hash value: 3145588588
| Id | Operation | Name | Starts | E-Rows |A-Rows | A-Time | Buffers |
|* 1 | FILTER | | 1 | | 0 |00:00:05.56 | 6818 | | 2 | HASH GROUP BY | | 1 | 104K| 1497K|00:00:10.35 | 6818 | | 3 | NESTED LOOPS | | 1 | 2089K| 2064K|00:00:18.58 | 6818 | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 75 | 73 |00:00:00.01 | 77 | |* 5 | INDEX RANGE SCAN | T1_INDEX1 | 1 | 75 | 73 |00:00:00.01 | 4 | |* 6 | INDEX RANGE SCAN | T1_INDEX3 | 73 | 27678| 2064K|00:00:08.26 | 6741 |
Predicate Information (identified by operation id):
1 - filter(COUNT(*)>10)
5 - access("T0"."RESIDENTID"=1486674)
6 - access("T0"."QUESTIONNUMBER"="TX"."QUESTIONNUMBER" AND
"T0"."ANSWER"="TX"."ANSWER")
filter(("T0"."RESIDENTID"<>"TX"."RESIDENTID" AND
"TX"."RESIDENTID"<>1486674))
So, the NESTED LOOPS operation took 18.58 seconds, the HASH GROUP BY 10.35 seconds, and the entire query returned in 5.56 seconds?
10053 TRACE:
+-----------------------------------+ | Id | Operation | Name | Rows | Bytes | Cost | Time | --------------------------------------------------- +-----------------------------------+ | 0 | SELECT STATEMENT | | | | 11K | | | 1 | FILTER | | | | | | | 2 | HASH GROUP BY | | 102K | 2244K | 11K | 00:01:02 | | 3 | NESTED LOOPS | | 2040K | 44M | 6944 | 00:00:38 | | 4 | TABLE ACCESS BY INDEX ROWID | T1 | 75 | 825 | 80 | 00:00:01 | | 5 | INDEX RANGE SCAN | T1_INDEX1| 75 | | 4 | 00:00:01 | | 6 | INDEX RANGE SCAN | T1_INDEX3| 27K | 297K| 92 | 00:00:01 |
+-----------------------------------+
1 - filter(COUNT(*)>10)
5 - access("T0"."RESIDENTID"=1486674)
6 - access("T0"."QUESTIONNUMBER"="TX"."QUESTIONNUMBER" AND
"T0"."ANSWER"="TX"."ANSWER")
So, the NESTED LOOPS operation took 38 seconds, and the HASH GROUP BY took 62 seconds?
10046 TRACE STAT LINES:
CPU Time 5.631636,Elapsed Time 5.562750,Rows Retrievd 0,Blks from Buff
6818,Blks from Disk 0
(Rows 0) FILTER (cr=6818 pr=0 pw=0 time=5562816 us)
(Rows 1497257) HASH GROUP BY (cr=6818 pr=0 pw=0 time=10349366 us)
(Rows 2064509) NESTED LOOPS (cr=6818 pr=0 pw=0 time=18580687 us)
(Rows 73) TABLE ACCESS BY INDEX ROWID T1 (cr=77 pr=0 pw=0
time=1943 us)
(Rows 73) INDEX RANGE SCAN T1_INDEX1 (cr=4 pr=0 pw=0
time=480 us)
(Rows 2064509) INDEX RANGE SCAN T1_INDEX3 (cr=6741 pr=0 pw=0
time=8260306 us)
So, the CPU time is 5.63 seconds, the elapsed time is 5.56 seconds?
And the stopwatch says - roughly 5 seconds.
If anyone finds value in the experiment, I will re-run the tests using 10046 trace output.
Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc.
Received on Wed Mar 21 2007 - 17:01:43 CDT
 |
 |