Re: --> outcome each time query ran slow AFTER 31 runs

From: Stephan <test_at_test.com>
Date: Mon, 06 Jan 2003 21:13:26 GMT
Message-ID: <WjmS9.29$MN3.284@nlnews00.chello.com>

If I read the line:
"Fetch 31 0.07 7.88 7 186 124 93"
then I conclude it took almost 8seconds to complete the query 31 times (resulting in 3 records each run).

But!: the response is very variable, sometimes 10msec sometimes 2seconds! <--- that
's what makes it so difficult for me. I better have a query which performs each run the same....

The outcome after 31 runs:

TKPROF: Release 8.1.7.0.0 - Production on Ma Jan 6 22:11:46 2003

Trace file: C:\oracle\admin\PREV\udump\ora01604.trc Sort options: default

count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
****************************************************************************

alter session set sql_trace=true

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.06 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 1 0.00 0.06 0 0 0 0

Misses in library cache during parse: 0
Misses in library cache during execute: 1 Optimizer goal: CHOOSE
Parsing user id: 20 (PREVENT)

select 'stephan'
from
dual

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 2 0.00 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 1 4 1
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 4 0.00 0.01 0 1 4 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 20 (PREVENT)

Rows Execution Plan

-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS (FULL) OF 'DUAL'

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

SELECT ORA_TQ_BASE$.NEXTVAL
FROM
DUAL call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 0 1 5 1
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 3 0.01 0.01 0 1 5 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)

Rows Row Source Operation

-------  ---------------------------------------------------
      1  SEQUENCE
      1   TABLE ACCESS FULL DUAL

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

update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6, cache=:7,highwater=:8,audit$=:9
where
obj#=:1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 1 3 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 2 0.00 0.00 0 1 3 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 2)

Rows Row Source Operation

-------  ---------------------------------------------------
      1  UPDATE SEQ$
      1   INDEX UNIQUE SCAN (object id 99)

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

select id_district district_id, district_name FROM district, district_street where
(district_id=id_district) AND (place_street_id=707)

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 62 0.09 0.11 0 0 0 0
Execute 31 0.01 3.21 1 93 279 0
Fetch 31 0.07 7.88 7 186 124 93
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 124 0.17 11.20 8 279 403 93

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 20 (PREVENT)

Rows Execution Plan

-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      0   HASH JOIN [:Q411002]
             SELECT /*+ ORDERED NO_EXPAND USE_HASH(A2) */ A1.C0,A1.C1 FROM

               :Q411001 A1,:Q411000 A2 WHERE A2.C0=A1.C0
      0    TABLE ACCESS   GOAL: ANALYZED (FULL) OF 'DISTRICT' [:Q411001]
              SELECT /*+ Q411001 NO_EXPAND ROWID(A1) */ A1."ID_DISTRICT" C0,
              A1."DISTRICT_NAME" C1 FROM "DISTRICT" PX_GRANULE(0,
                BLOCK_RANGE, DYNAMIC)  A1
      0    INDEX   GOAL: ANALYZED (FAST FULL SCAN) OF 'DISTRICT_STREET_4'
               (NON-UNIQUE) [:Q411000]




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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 64 0.09 0.12 0 0 0 0
Execute 33 0.01 3.27 1 93 279 0
Fetch 32 0.07 7.88 7 187 128 94
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 129 0.17 11.27 8 280 407 94

Misses in library cache during parse: 2
Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 1 3 1
Fetch 1 0.01 0.01 0 1 5 1
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 5 0.01 0.01 0 2 8 2

Misses in library cache during parse: 2

   65 user SQL statements in session.
    2 internal SQL statements in session.    67 SQL statements in session.
    2 statements EXPLAINed in this session.

Trace file: C:\oracle\admin\PREV\udump\ora01604.trc Trace file compatibility: 8.00.04
Sort options: default

       1  session in tracefile.
      65  user  SQL statements in trace file.
       2  internal SQL statements in trace file.
      67  SQL statements in trace file.
       5  unique SQL statements in trace file.
       2  SQL statements EXPLAINed using schema:
           PREVENT.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
     643  lines in trace file.

Received on Mon Jan 06 2003 - 15:13:26 CST