Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Re: Help with sql query speed. Explain plan included

Re: Help with sql query speed. Explain plan included

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: 21 Mar 2007 15:01:43 -0700
Message-ID: <1174514503.262272.84260@n59g2000hsh.googlegroups.com>


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

PVAL1
------------------------------ ------------------------------
----------
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

PVAL1
------------------------------ ------------------------------
----------
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 |
| 2 | INDEX FAST FULL SCAN | SYS_C007848| 491K | 2947K | 384 | 00:00:06 |
| 3 | TABLE ACCESS FULL | TA | 489K | 6354K | 530 | 00:00:09 |
+-----------------------------------+

Predicate Information:

1 - access("TA"."PK"="TB"."PK")

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 |
| 2 | INDEX FAST FULL SCAN | SYS_C007848| 491K | 2947K | 218 | 00:00:02 |
| 3 | TABLE ACCESS FULL | TA | 489K | 6354K | 304 | 00:00:02 |
+-----------------------------------+

Predicate Information:

1 - access("TA"."PK"="TB"."PK")

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 |
+-----------------------------------+

Predicate Information:
1 - filter(COUNT(*)>10)
5 - access("T0"."RESIDENTID"=1486674)
6 - access("T0"."QUESTIONNUMBER"="TX"."QUESTIONNUMBER" AND
"T0"."ANSWER"="TX"."ANSWER")
6 - filter(("T0"."RESIDENTID"<>"TX"."RESIDENTID" AND "TX"."RESIDENTID"<>1486674))

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

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US