Prev: So is 11.2.0.2 going to be out anytime soon?
Next: Ora-19906 when restoring user managed backup - stumped!
From: Mladen Gogala on 10 Sep 2009 07:20
Na Thu, 10 Sep 2009 02:20:49 -0700, Gerard H. Pille napisao:

> On 10 sep, 10:26, Mladen Gogala wrote:
>
>
>> Question: was direct I/O enabled here? If not, the blocks may have been
>> in the system buffer cache in which case oracle would still report them
>> as "physical reads" but blocks would be coming from memory instead.
>>
>>
>
> Why do you ask this? Charles clearly states that it was not. Will you
> believe him next time??

Because this was the new execution and I lost track of the other
conditions. If direct I/O was disabled, Linux buffer cache would have
contained the cached blocks and that would explain the difference in
performance.



--
http://mgogala.freehostia.com
From: Charles Hooper on 11 Sep 2009 08:11
No direct I/O was disabled, I left the FILESYSTEMIO_OPTIONS parameter
unset, which should have caused Oracle to use file system buffered I/O
if I understand the documentation correctly.

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.

Also interesting is that on 11.2.0.1 with the SGA_TARGET set to 8000M,
the DB_KEEP_CACHE_SIZE set to 6G, and the table and its index using
the default buffer pool, I am seeing somewhat unexpected values for a
couple of the hidden parameters at the end of the run with the full
index access path (1 to 400) with direct I/O enabled and asychronous I/
O enabled. __DB_CACHE_SIZE was set to 536,870,912 (512MB).
__SHARED_POOL_SIZE was set to 1,140,850,688 (1,088MB). It would seem
that Oracle should have at the least set __DB_CACHE_SIZE to a value
larger than the __SHARED_POOL_SIZE value as it did on 10.2.0.4
(Windows 64 bit), 11.1.0.7 (Windows 64 bit), and 11.1.0.6 (Linux 64
bit). This might explain why the test run required slightly longer on
11.2.0.1.

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
From: Charles Hooper on 11 Sep 2009 08:24
On Sep 11, 8:11 am, Charles Hooper <hooperc2...(a)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.
First  |  Prev  | 
Pages: 1 2 3 4 5
Prev: So is 11.2.0.2 going to be out anytime soon?
Next: Ora-19906 when restoring user managed backup - stumped!