Re: Surprising Performance Changes with Oracle 11.2.0.1 (Long Post)
Date: Fri, 11 Sep 2009 05:24:57 -0700 (PDT)
Message-ID: <c935995f-7336-4986-86c0-c282e5ca354b_at_d23g2000vbm.googlegroups.com>
On Sep 11, 8:11 am, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
> If this post makes it out to Usenet (the posts were failing yesterday
> through Google's interface), I will post the results of 3 test runs of
> the second script (suggested by Gerard) with direct I/O and with a
> reboot between each test run. It is interesting to see Oracle aging
> out the blocks read during the test run shortly after the test run
> completes, even with no other load on the system and the test run
> should not have encountered an AWR collection.
Output from the first test run:
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 100K| 5273K| 99458 (1)| 00:19:54 | | 1 | TABLE ACCESS BY INDEX ROWID| T1 | 100K| 5273K| 99458 (1)| 00:19:54 | |* 2 | INDEX RANGE SCAN | IND_T1 | 100K| | 212(1)| 00:00:03 |
Predicate Information (identified by operation id):
2 - access("ID">=9991)
2847287 rows selected.
Elapsed: 00:08:09.31
Statistics
8 recursive calls
0 db block gets
2568572 consistent gets
2540350 physical reads
0 redo size
173286364 bytes sent via SQL*Net to client
313716 bytes received via SQL*Net from client
28474 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2847287 rows processed
2847287 rows selected.
Elapsed: 00:08:10.87
Statistics
8 recursive calls
0 db block gets
2568572 consistent gets
2536953 physical reads
0 redo size
173286364 bytes sent via SQL*Net to client
313716 bytes received via SQL*Net from client
28474 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2847287 rows processed
Output from the second test run (after a reboot): 2847287 rows selected.
Elapsed: 00:08:01.98
Statistics
3 recursive calls
0 db block gets
2568572 consistent gets
2540183 physical reads
0 redo size
173286364 bytes sent via SQL*Net to client
313716 bytes received via SQL*Net from client
28474 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2847287 rows processed
2847287 rows selected.
Elapsed: 00:08:04.46
Statistics
0 recursive calls
0 db block gets
2568572 consistent gets
2536953 physical reads
0 redo size
173286364 bytes sent via SQL*Net to client
313716 bytes received via SQL*Net from client
28474 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2847287 rows processed
Output from the third test run (after a reboot): 2847287 rows selected.
Elapsed: 00:08:05.50
Statistics
5 recursive calls
0 db block gets
2568572 consistent gets
2540176 physical reads
0 redo size
173286364 bytes sent via SQL*Net to client
313716 bytes received via SQL*Net from client
28474 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2847287 rows processed
2847287 rows selected.
Elapsed: 00:07:55.58
Statistics
0 recursive calls
0 db block gets
2568572 consistent gets
2536953 physical reads
0 redo size
173286364 bytes sent via SQL*Net to client
313716 bytes received via SQL*Net from client
28474 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2847287 rows processed
After the first execution of the script I noticed that when the server sat idle for a couple minutes the number of blocks remaining in the buffer cache for the table and index continued to decrease. For the final execution of the script I monitored the number of blocks remaining in the buffer cache:
Immediately after the two SQL statements ended (481.73 MB):
OBJECT_NAME STATUS BLOCKS
------------- ---------- ----------
T1 xcur 61507 IND_T1 xcur 155 Two minutes after the the two SQL statements ended (481.51 MB) OBJECT_NAME STATUS BLOCKS ------------- ---------- ---------- T1 xcur 61479 IND_T1 xcur 155 Four minutes after the the two SQL statements ended (481.51 MB) OBJECT_NAME STATUS BLOCKS ------------- ---------- ---------- T1 xcur 61417 IND_T1 xcur 154 Six minutes after the the two SQL statements ended (481.02 MB) OBJECT_NAME STATUS BLOCKS ------------- ---------- ---------- T1 xcur 60947 IND_T1 xcur 153
After rebooting the server again, I executed just the index range scan portion of the original script (BETWEEN 1 AND 400) so that I could answer Jonathan's question about the number of blocks remaining in the buffer cache at the end of the run:
Execution Plan
Plan hash value: 634656657
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 4000K| 206M| 198K (1)| 00:39:47 | | 1 | TABLE ACCESS BY INDEX ROWID| T1 | 4000K| 206M| 198K (1)| 00:39:47 | |* 2 | INDEX RANGE SCAN | IND_T1 | 4000K| | 420(1)| 00:00:06 |
Predicate Information (identified by operation id):
2 - access("ID">=1 AND "ID"<=400)
System altered.
Elapsed: 00:00:00.04
System altered.
Elapsed: 00:00:00.02
Session altered.
Elapsed: 00:00:00.00
Session altered.
Elapsed: 00:00:00.04
Session altered.
Elapsed: 00:00:00.00
2547158 rows selected.
Elapsed: 01:16:03.82
Statistics
6 recursive calls
0 db block gets
2573633 consistent gets
2463148 physical reads
0 redo size
17418653 bytes sent via SQL*Net to client
280705 bytes received via SQL*Net from
client
25473 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2547158 rows processed
Immediately after the two SQL statements ended (488.01 MB)
OBJECT_NAME STATUS BLOCKS
------------- ---------- ----------
T1 xcur 62400 IND_T1 xcur 65 Two minutes after the the two SQL statements ended OBJECT_NAME STATUS BLOCKS ------------- ---------- ---------- T1 xcur 62255 IND_T1 xcur 65 Four minutes after the the two SQL statements ended OBJECT_NAME STATUS BLOCKS ------------- ---------- ---------- T1 xcur 62236 IND_T1 xcur 65 Six minutes after the the two SQL statements ended OBJECT_NAME STATUS BLOCKS ------------- ---------- ---------- T1 xcur 62196 IND_T1 xcur 65
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Received on Fri Sep 11 2009 - 07:24:57 CDT