| Why Elapsed Time Changed while execution plan and stats remains the same? [message #459302] |
Fri, 04 June 2010 06:17  |
chetanaZ
Messages: 132
Registered: October 2009
Location: UK
|
Senior Member |
|
|
Hi,
Please refer attached query giving consistent execution plan but different timings across run
SELECT /*+ INDEX (CRT CRT_CUN_FK_I)*/
DISTINCT odr.dve_id
FROM company_requirements crt, orders odr, lelo_products la_pct
WHERE crt.qtn_cun_id = 10035637--10000021--10035667
AND crt.ID = odr.crt_id_quote_implemented
AND NVL (odr.cancellation_date, '31-Dec-9999') = '31-Dec-9999'
AND crt.crt_pct_id_branded = la_pct.ID
AND la_pct.pct_used = 'Y'
AND la_pct.release = 'T4'
AND odr.dve_id IS NOT NULL
AND NOT EXISTS (SELECT /*+ INDEX (COT COT_ODR_FK_I)*/
'X'
FROM contracts cot
WHERE cot.odr_id = odr.ID AND ROWNUM <= 1)
we have 4 databases, 2 on each servers, such that db1 and db2 on server1
and db3 and db4 on server2
Please refer count of the records for column of biggest table in the query, taken on all 4 databases
(The column is nullable)
select count(*) from company_requirements crt WHERE crt.qtn_cun_id = 10035637
db1 = 73335
db2 = 89073
db3 = 81182
db4 = 82936
First I executed the query on db1 and db2 while there wasn't any user logged on to the system
db1
**********
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.08 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 17.47 473.39 85704 1508102 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 17.53 473.48 85704 1508102 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 11871
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT UNIQUE
0 FILTER
0 TABLE ACCESS BY INDEX ROWID ORDERS
75553 NESTED LOOPS
73335 NESTED LOOPS
31 TABLE ACCESS FULL lelo_products
73335 TABLE ACCESS BY INDEX ROWID company_requirements
2273385 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
2217 INDEX RANGE SCAN ODR_CRT_QUOTE_IMPLEMENTED_FK_I (object id 130446)
0 COUNT STOPKEY
0 INDEX RANGE SCAN COT_ODR_FK_I (object id 129777)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
db file sequential read 85704 0.31 460.55
latch free 1 0.00 0.00
SQL*Net message from client 1 14.98 14.98
db2
**********
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.08 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 18.02 459.99 79460 1740746 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 18.08 460.07 79460 1740746 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 11871
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT UNIQUE
0 FILTER
0 TABLE ACCESS BY INDEX ROWID ORDERS
91297 NESTED LOOPS
89073 NESTED LOOPS
31 TABLE ACCESS FULL lelo_products
89073 TABLE ACCESS BY INDEX ROWID company_requirements
2761263 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
2223 INDEX RANGE SCAN ODR_CRT_QUOTE_IMPLEMENTED_FK_I (object id 130446)
0 COUNT STOPKEY
0 INDEX RANGE SCAN COT_ODR_FK_I (object id 129777)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
db file sequential read 79460 0.26 446.21
latch free 3 0.00 0.00
SQL*Net message from client 1 39.48 39.48
after some time when I executed it I got surprisng results
db1
*********
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 8.78 8.62 0 1508086 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 8.84 8.69 0 1508086 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 11871
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT UNIQUE
0 FILTER
0 TABLE ACCESS BY INDEX ROWID ORDERS
75553 NESTED LOOPS
73335 NESTED LOOPS
31 TABLE ACCESS FULL lelo_products
73335 TABLE ACCESS BY INDEX ROWID company_requirements
2273385 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
2217 INDEX RANGE SCAN ODR_CRT_QUOTE_IMPLEMENTED_FK_I (object id 130446)
0 COUNT STOPKEY
0 INDEX RANGE SCAN COT_ODR_FK_I (object id 129777)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 28.22 28.22
db2
**********
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.08 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 10.66 21.87 33 1740746 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 10.73 21.95 33 1740746 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 11871
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT UNIQUE
0 FILTER
0 TABLE ACCESS BY INDEX ROWID ORDERS
91297 NESTED LOOPS
89073 NESTED LOOPS
31 TABLE ACCESS FULL lelo_products
89073 TABLE ACCESS BY INDEX ROWID company_requirements
2761263 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
2223 INDEX RANGE SCAN ODR_CRT_QUOTE_IMPLEMENTED_FK_I (object id 130446)
0 COUNT STOPKEY
0 INDEX RANGE SCAN COT_ODR_FK_I (object id 129777)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
db file sequential read 33 0.00 0.01
buffer busy waits 2060 0.05 11.03
latch free 10 0.10 0.16
SQL*Net message from client 1 6.86 6.86
Also the above query remained same for db3 and db4 (on another server) and timing remains consistently low
db3
*********
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.09 1 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.00 5 7 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.08 0.09 6 8 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 11871
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT UNIQUE
0 FILTER
0 TABLE ACCESS BY INDEX ROWID ORDERS
1 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS FULL lelo_products
0 TABLE ACCESS BY INDEX ROWID company_requirements
0 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
0 INDEX RANGE SCAN ODR_CRT_QUOTE_IMPLEMENTED_FK_I (object id 130446)
0 COUNT STOPKEY
0 INDEX RANGE SCAN COT_ODR_FK_I (object id 129777)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
db file scattered read 1 0.00 0.00
SQL*Net message from client 1 76.95 76.95
db4
********
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.08 0.08 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.02 5 7 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.08 0.10 5 7 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 11871
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT UNIQUE
0 FILTER
0 TABLE ACCESS BY INDEX ROWID ORDERS
1 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS FULL lelo_products
0 TABLE ACCESS BY INDEX ROWID company_requirements
0 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
0 INDEX RANGE SCAN ODR_CRT_QUOTE_IMPLEMENTED_FK_I (object id 130446)
0 COUNT STOPKEY
0 INDEX RANGE SCAN COT_ODR_FK_I (object id 129777)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
db file sequential read 2 0.01 0.02
db file scattered read 1 0.00 0.00
SQL*Net message from client 1 8.42 8.42
Why the elasped time changed when data and plan hasn't changed at all?
Also why the plan has different stats for round 1 and 2 on db1 and db2?
I ran it 2 times each round each database so hard parsing shall not be issue.
Also why the number of rows accessed are different in db1,db2 and db3,db4 especially for step1 when count of crt.qtn_cun_id is similar?
In fact when the query was taking long I was the only user on the system
Also I used hard coded value (no bind variables at all)
I checked num_rows, distinct keys as well which are quite similar across all 4 databases
Also no stats where gather during the query execution
What I should have checked or monitored?
Thanks and Regards,
Chetana
|
|
|
|
|
|
| Re: Why Elapsed Time Changed while execution plan and stats remains the same? [message #459309 is a reply to message #459302] |
Fri, 04 June 2010 06:34  |
cookiemonster
Messages: 13922
Registered: September 2008
Location: Rainy Manchester
|
Senior Member |
|
|
As far as the changing values on db1 and db2 go the main obvious difference is the disk counts.
Disk means reads from the physical disk.
It starts high then drops like a stone because the data will have been loaded into memory. Reading the data from memory is a lot quicker than reading it from disk.
You can see also that the db file sequential read wait has dropped massively which indicates the same thing.
As for why db3 and db4 are different, you'll have to look at your data.
It's obvious from the trace that the query didn't find anywhere near as many matching rows on those dbs as it did on 1 and 2.
|
|
|
|
| Re: Why Elapsed Time Changed while execution plan and stats remains the same? [message #459311 is a reply to message #459305] |
Fri, 04 June 2010 06:36 |
chetanaZ
Messages: 132
Registered: October 2009
Location: UK
|
Senior Member |
|
|
Hello ThomasG
Thanks for the quick reply
I agree there were quite lot of sequential reads initinally but i executed it twice each round
2 executions on db1, 2 executions on db2 - similar timing 450+ secnds
2 executions on db3 2 executions on db4 - similar timings around 0.10 conds
After some time
2 executions on db1, 2 executions on db2 - similar timings less than 20 seconds
Unfortunately I do not have trace for each execution
So the questions remained are
1)why the sequentials reads were dropped after some time on db1, db2
2) why we can't see different stats in the plan of db3,db4 when number of records for at least 1st step are similar?
Thanks and Regards,
Chetana
|
|
|
|
|
|
| Re: Why Elapsed Time Changed while execution plan and stats remains the same? [message #459344 is a reply to message #459314] |
Fri, 04 June 2010 07:54 |
chetanaZ
Messages: 132
Registered: October 2009
Location: UK
|
Senior Member |
|
|
Hello cookiemonster,
Quote:
1) Because the data got loaded into RAM. This should have happened after the first execution but there might have been other stuff happening that would prevent that.
That's the point.
I checked on the server when there were no users logged on the system while I was executing first round on db1 and db2
I checked with 'top', sar -b OS command as well
Nothing was abnormal
Apart from sar I could not checked I/O, as I am not aware of such commands, utility
Quote:
What do you expect to see?
i) since consecutive 2 executions on db1, db2 took 450+ seconds while there wasn't load on the server I expect other 2 executions triggered after some time shall take at least that much time as the plan , stats did not changed
ii) When data is similar on db1,db2,db3,db4 for at least
"customer_requirements crt WHERE crt.qtn_cun_id = 10035637"
at least the fisrt step in the plan shall show similar statistics
on db1,db2,db3,db4
regardless of other steps
89073 TABLE ACCESS BY INDEX ROWID CUSTOMER_REQUIREMENTS
2761263 INDEX RANGE SCAN CRT_CUN_FK_I (object id 130845)
Thanks and Regards,
Chetana
|
|
|
|
|
|
|
|
|
|
|
|
|
|
] 
Blog
Search
Help
Members
Register
Login
Home
