Re: Surprising Performance Changes with Oracle 11.2.0.1 (Long Post)
Date: Sat, 5 Sep 2009 08:28:54 -0700 (PDT)
Message-ID: <20921d95-425c-4a2e-8442-cd075cef541a_at_q14g2000vbi.googlegroups.com>
On Sep 5, 2:04 am, "Jonathan Lewis" <jonat..._at_jlcomp.demon.co.uk> wrote:
> > "Charles Hooper" <hooperc2..._at_yahoo.com> wrote in message
> >news:1ea99c67-8713-4ece-a0f5-85f66851b016_at_v2g2000vbb.googlegroups.com...
> > I am working on an Oracle performance related project, so I thought
> > that I would compare the performance of Oracle database 11.1.0.6 (on
> > 64 bit Linux), 11.1.0.7 (on 64 bit Windows), and 11.2.0.1 (on 64 bit
> > Linux).
>
> ...
>
> Charles,
>
> Interesting figures.
> A couple of follow-on questions:
> How much memory in the machine ?
> How many CPUs
> Were you running the client locally - ipc or tcp
> How much CPU usage "outside" Oracle in each test
> Any significant variation in 'prefetch' blocks
> Any other significant variation in stats
>
> --
> Regards
>
> Jonathan Lewis
> http://jonathanlewis.wordpress.com
>
> Author: Cost Based Oracle: Fundamentalshttp://www.jlcomp.demon.co.uk/cbo_book/ind_book.html
>
> The Co-operative Oracle Users' FAQhttp://www.jlcomp.demon.co.uk/faq/ind_faq.html
12GB of memory, 1 CPU (a Core i7 940 at 2.93GHz), local connection with no listener started.
Robert, good question. Yes, table and index stats were collected with no histograms.
A short sampling of the waits found during the index scan (near the
start of the trace) with an unset FILESYSTEMIO_OPTIONS (69689 is the
table, 69690 is the index):
FETCH
#8:c=0,e=897,p=100,cr=101,cu=0,mis=0,r=100,dep=0,og=1,plh=634656657,tim=1252080204301576
WAIT #8: nam='SQL*Net message from client' ela= 103 driver
id=1650815232 #bytes=1 p3=0 obj#=69689 tim=1252080204301706
WAIT #8: nam='db file parallel read' ela= 173 files=1 blocks=39
requests=39 obj#=69689 tim=1252080204301959
WAIT #8: nam='db file sequential read' ela= 7 file#=7 block#=1350890
blocks=1 obj#=69689 tim=1252080204302009
WAIT #8: nam='SQL*Net message to client' ela= 1 driver id=1650815232
#bytes=1 p3=0 obj#=69689 tim=1252080204302022
WAIT #8: nam='db file parallel read' ela= 192 files=1 blocks=39
requests=39 obj#=69689 tim=1252080204302283
WAIT #8: nam='db file sequential read' ela= 7 file#=7 block#=1356525
blocks=1 obj#=69689 tim=1252080204302373
WAIT #8: nam='db file scattered read' ela= 33 file#=7 block#=2162857
blocks=7 obj#=69690 tim=1252080204302442
WAIT #8: nam='db file parallel read' ela= 88 files=1 blocks=19
requests=19 obj#=69689 tim=1252080204302579
WAIT #8: nam='db file sequential read' ela= 7 file#=7 block#=1361383
blocks=1 obj#=69689 tim=1252080204302666
FETCH
#8:c=1000,e=982,p=107,cr=102,cu=0,mis=0,r=100,dep=0,og=1,plh=634656657,tim=1252080204302701
WAIT #8: nam='SQL*Net message from client' ela= 105 driver
id=1650815232 #bytes=1 p3=0 obj#=69689 tim=1252080204302823
WAIT #8: nam='db file parallel read' ela= 178 files=1 blocks=39
requests=39 obj#=69689 tim=1252080204303081
WAIT #8: nam='db file sequential read' ela= 7 file#=7 block#=1364081
blocks=1 obj#=69689 tim=1252080204303130
WAIT #8: nam='SQL*Net message to client' ela= 1 driver id=1650815232
#bytes=1 p3=0 obj#=69689 tim=1252080204303143
WAIT #8: nam='db file parallel read' ela= 174 files=1 blocks=39
requests=39 obj#=69689 tim=1252080204303381
WAIT #8: nam='db file sequential read' ela= 8 file#=7 block#=1369027
blocks=1 obj#=69689 tim=1252080204303468
WAIT #8: nam='db file parallel read' ela= 98 files=1 blocks=19
requests=19 obj#=69689 tim=1252080204303613
WAIT #8: nam='db file sequential read' ela= 7 file#=7 block#=1373988
blocks=1 obj#=69689 tim=1252080204303719
FETCH
#8:c=1000,e=921,p=100,cr=101,cu=0,mis=0,r=100,dep=0,og=1,plh=634656657,tim=1252080204303757
In the above, note the impossibly fast times for the waits - this is fairly consistent through the trace file. The index blocks were read by db file scattered read, db file sequential read, but a quick check of the file did not seem to indicate that db file parallel read was used for the index blocks. The table blocks were read by db file scattered read, db file sequential read, and db file parallel read.
A short sampling of the waits found during the index scan (near the
start of the trace) with FILESYSTEMIO_OPTIONS set to SetAll (69689 is
the table, 69690 is the index):
FETCH
#8:c=2000,e=251016,p=100,cr=101,cu=0,mis=0,r=100,dep=0,og=1,plh=634656657,tim=1252088662939190
WAIT #8: nam='SQL*Net message from client' ela= 200 driver
id=1650815232 #bytes=1 p3=0 obj#=69689 tim=1252088662939432
WAIT #8: nam='db file parallel read' ela= 94215 files=1 blocks=39
requests=39 obj#=69689 tim=1252088663033884
WAIT #8: nam='db file sequential read' ela= 5612 file#=7 block#=1397615 blocks=1 obj#=69689 tim=1252088663039645 WAIT #8: nam='SQL*Net message to client' ela= 2 driver id=1650815232#bytes=1 p3=0 obj#=69689 tim=1252088663039684 WAIT #8: nam='db file parallel read' ela= 74655 files=1 blocks=39 requests=39 obj#=69689 tim=1252088663114551
WAIT #8: nam='db file sequential read' ela= 3377 file#=7 block#=1402576 blocks=1 obj#=69689 tim=1252088663118159 WAIT #8: nam='db file parallel read' ela= 41403 files=1 blocks=19requests=19 obj#=69689 tim=1252088663159699 WAIT #8: nam='db file sequential read' ela= 8198 file#=7 block#=1407689 blocks=1 obj#=69689 tim=1252088663168086 FETCH
#8:c=2999,e=228700,p=100,cr=101,cu=0,mis=0,r=100,dep=0,og=1,plh=634656657,tim=1252088663168161 WAIT #8: nam='SQL*Net message from client' ela= 219 driver id=1650815232 #bytes=1 p3=0 obj#=69689 tim=1252088663168420 WAIT #8: nam='db file scattered read' ela= 7961 file#=7 block#=1346037 blocks=3 obj#=69690 tim=1252088663176493 WAIT #8: nam='db file parallel read' ela= 61848 files=1 blocks=39 requests=39 obj#=69689 tim=1252088663238666
WAIT #8: nam='db file sequential read' ela= 54241 file#=7 block#=1410476 blocks=1 obj#=69689 tim=1252088663293049 WAIT #8: nam='SQL*Net message to client' ela= 2 driver id=1650815232#bytes=1 p3=0 obj#=69689 tim=1252088663293115 WAIT #8: nam='db file parallel read' ela= 87347 files=1 blocks=39 requests=39 obj#=69689 tim=1252088663380663
WAIT #8: nam='db file sequential read' ela= 9152 file#=7 block#=1415385 blocks=1 obj#=69689 tim=1252088663390014 WAIT #8: nam='db file parallel read' ela= 30242 files=1 blocks=19requests=19 obj#=69689 tim=1252088663420387 WAIT #8: nam='db file sequential read' ela= 6660 file#=7 block#=1420835 blocks=1 obj#=69689 tim=1252088663427228 FETCH
#8:c=4000,e=258841,p=103,cr=102,cu=0,mis=0,r=100,dep=0,og=1,plh=634656657,tim=1252088663427311
Elapsed time for the full tablescan with with direct I/O and asynch I/ O and other monitoring enabled: roughly 42 seconds
Top output with direct I/O and asynch I/O enabled during the full
tablescan operation (terminated about 5 seconds into the run):
top - 09:48:21 up 1:40, 4 users, load average: 0.42, 0.23, 0.15
Tasks: 244 total, 1 running, 243 sleeping, 0 stopped, 0 zombie
Cpu(s): 3.7%us, 1.0%sy, 0.0%ni, 85.5%id, 9.6%wa, 0.2%hi,
0.1%si, 0.0%st
Mem: 12291184k total, 1694080k used, 10597104k free, 93000k
buffers
Swap: 14352376k total, 0k used, 14352376k free, 1123524k
cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
COMMAND
7090 oracle 16 0 8416m 125m 112m S 24.3 1.0 0:10.34
oracle
7082 oracle 18 0 65468 12m 9032 S 9.6 0.1 0:04.15
sqlplus
4966 oracle 15 0 284m 18m 8964 S 2.3 0.2 0:03.53 gnome-
terminal
4848 oracle 15 0 492m 30m 12m S 0.7 0.3 0:18.77
nautilus
718 root 10 -5 0 0 0 S 0.3 0.0 0:05.19 usb-
storage
...
V$OSSTAT delta values (60 second capture) with direct I/O and asynch I/ O enabled during the full tablescan operation:
STAT_NAME END_VALUE DELTA DELTA_SEC ------------------------- ---------- ----------- ------------ BUSY_TIME 5912 1759 29.32 GLOBAL_RECEIVE_SIZE_MAX 4194304 0 0.00 GLOBAL_SEND_SIZE_MAX 1048586 0 0.00 IDLE_TIME 864418 46730 778.83 IOWAIT_TIME 4973 3424 57.07 LOAD .319335938 0 0.00 NICE_TIME 0 0 0.00 NUM_CPUS 8 0 0.00 NUM_CPU_CORES 4 0 0.00 NUM_CPU_SOCKETS 1 0 0.00 PHYSICAL_MEMORY_BYTES 1.2586E+10 0 0.00 RSRC_MGR_CPU_WAIT_TIME 0 0 0.00 SYS_TIME 1353 383 6.38 TCP_RECEIVE_SIZE_DEFAULT 87380 0 0.00 TCP_RECEIVE_SIZE_MAX 4194304 0 0.00 TCP_RECEIVE_SIZE_MIN 4096 0 0.00 TCP_SEND_SIZE_DEFAULT 16384 0 0.00 TCP_SEND_SIZE_MAX 4194304 0 0.00 TCP_SEND_SIZE_MIN 4096 0 0.00 USER_TIME 4120 1266 21.10
V$SYS_TIME_MODEL delta values (60 second capture) with direct I/O and asynch I/O enabled during the full tablescan operation:
STAT_NAME DELTADELTA_SEC
-------------------------------------------------- ----------- ------------ DB CPU 10574389 176239.82 DB time 40284606 671410.10 Java execution elapsed time 0 0.00 PL/SQL compilation elapsed time 135017 2250.28 PL/SQL execution elapsed time 799537 13325.62 RMAN cpu time (backup/restore) 0 0.00 background cpu time 262959 4382.65 background elapsed time 6982341 116372.35 connection management call elapsed time 310170 5169.50 failed parse (out of shared memory) elapsed time 0 0.00 failed parse elapsed time 0 0.00 hard parse (bind mismatch) elapsed time 62740 1045.67 hard parse (sharing criteria) elapsed time 114156 1902.60 hard parse elapsed time 3062463 51041.05 inbound PL/SQL rpc elapsed time 0 0.00 parse time elapsed 3414383 56906.38 repeated bind elapsed time 7238 120.63 sequence load elapsed time 9007 150.12 sql execute elapsed time 39621673660361.22
Elapsed time for the full tablescan with other monitoring enabled: 11.97 seconds
Top output with unset filesystemio_options during the full tablescan
operation (terminated about 5 seconds into the run):
top - 10:26:47 up 2:18, 4 users, load average: 0.41, 0.28, 0.20
Tasks: 245 total, 2 running, 243 sleeping, 0 stopped, 0 zombie
Cpu(s): 9.5%us, 3.6%sy, 0.0%ni, 86.8%id, 0.1%wa, 0.0%hi,
0.0%si, 0.0%st
Mem: 12291184k total, 8364088k used, 3927096k free, 95948k
buffers
Swap: 14352376k total, 0k used, 14352376k free, 7768492k
cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
COMMAND
7936 oracle 18 0 8416m 138m 125m S 74.2 1.2 0:20.07
oracle
4994 oracle 18 0 69240 16m 9392 R 25.6 0.1 0:16.30
sqlplus
4727 root 15 0 173m 43m 23m S 1.7 0.4 1:26.83
Xorg
4848 oracle 15 0 492m 30m 12m S 1.3 0.3 0:25.46
nautilus
7870 oracle 16 0 8401m 69m 67m S 0.7 0.6 0:00.14 oracle
...
V$OSSTAT delta values (60 second capture) with unset filesystemio_options during the full tablescan operation:
STAT_NAME END_VALUE DELTA DELTA_SEC ------------------------- ---------- ----------- ------------ BUSY_TIME 4843 1464 24.40 GLOBAL_RECEIVE_SIZE_MAX 4194304 0 0.00 GLOBAL_SEND_SIZE_MAX 1048586 0 0.00 IDLE_TIME 194252 46582 776.37 IOWAIT_TIME 66 30 0.50 LOAD .559570313 0 0.00 NICE_TIME 0 0 0.00 NUM_CPUS 8 0 0.00 NUM_CPU_CORES 4 0 0.00 NUM_CPU_SOCKETS 1 0 0.00 PHYSICAL_MEMORY_BYTES 1.2586E+10 0 0.00 RSRC_MGR_CPU_WAIT_TIME 0 0 0.00 SYS_TIME 1218 380 6.33 TCP_RECEIVE_SIZE_DEFAULT 87380 0 0.00 TCP_RECEIVE_SIZE_MAX 4194304 0 0.00 TCP_RECEIVE_SIZE_MIN 4096 0 0.00 TCP_SEND_SIZE_DEFAULT 16384 0 0.00 TCP_SEND_SIZE_MAX 4194304 0 0.00 TCP_SEND_SIZE_MIN 4096 0 0.00 USER_TIME 3561 1067 17.78
V$SYS_TIME_MODEL delta values (60 second capture) with unset filesystemio_options during the full tablescan operation:
STAT_NAME DELTADELTA_SEC
-------------------------------------------------- ----------- ------------ DB CPU 9641528 160692.13 DB time 10092101 168201.68 Java execution elapsed time 0 0.00 PL/SQL compilation elapsed time 49928 832.13 PL/SQL execution elapsed time 227048 3784.13 RMAN cpu time (backup/restore) 0 0.00 background cpu time 124977 2082.95 background elapsed time 339846 5664.10 connection management call elapsed time 42929 715.48 failed parse (out of shared memory) elapsed time 0 0.00 failed parse elapsed time 0 0.00 hard parse (bind mismatch) elapsed time 718 11.97 hard parse (sharing criteria) elapsed time 48453 807.55 hard parse elapsed time 1029104 17151.73 inbound PL/SQL rpc elapsed time 0 0.00 parse time elapsed 1324548 22075.80 repeated bind elapsed time 21478 357.97 sequence load elapsed time 4464 74.40 sql execute elapsed time 9611995160199.92
here
Elapsed time for the index access with other monitoring enabled: 23.44 seconds
Top output with unset filesystemio_options during the index scan
operation (terminated about 5 seconds into the run):
top - 10:41:56 up 2:33, 4 users, load average: 0.10, 0.09, 0.12
Tasks: 247 total, 2 running, 245 sleeping, 0 stopped, 0 zombie
Cpu(s): 7.4%us, 5.0%sy, 0.0%ni, 87.1%id, 0.4%wa, 0.1%hi,
0.0%si, 0.0%st
Mem: 12291184k total, 8811144k used, 3480040k free, 97216k
buffers
Swap: 14352376k total, 0k used, 14352376k free, 8205800k
cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
COMMAND
7936 oracle 18 0 8412m 652m 641m R 88.5 5.4 0:32.71
oracle
4994 oracle 18 0 69240 16m 9392 S 9.3 0.1 0:19.61
sqlplus
7924 oracle 15 0 8405m 74m 68m S 0.7 0.6 0:00.43
oracle
6 root 34 19 0 0 0 S 0.3 0.0 0:02.67 ksoftirqd/
1
718 root 10 -5 0 0 0 S 0.3 0.0 0:08.02 usb-
storage
...
V$OSSTAT delta values (60 second capture) with unset filesystemio_options during the index scan operation:
STAT_NAME END_VALUE DELTA DELTA_SEC ------------------------- ---------- ----------- ------------ BUSY_TIME 9826 2459 40.98 GLOBAL_RECEIVE_SIZE_MAX 4194304 0 0.00 GLOBAL_SEND_SIZE_MAX 1048586 0 0.00 IDLE_TIME 913964 45579 759.65 IOWAIT_TIME 256 123 2.05 LOAD .33984375 0 0.01 NICE_TIME 0 0 0.00 NUM_CPUS 8 0 0.00 NUM_CPU_CORES 4 0 0.00 NUM_CPU_SOCKETS 1 0 0.00 PHYSICAL_MEMORY_BYTES 1.2586E+10 0 0.00 RSRC_MGR_CPU_WAIT_TIME 0 0 0.00 SYS_TIME 2807 962 16.03 TCP_RECEIVE_SIZE_DEFAULT 87380 0 0.00 TCP_RECEIVE_SIZE_MAX 4194304 0 0.00 TCP_RECEIVE_SIZE_MIN 4096 0 0.00 TCP_SEND_SIZE_DEFAULT 16384 0 0.00 TCP_SEND_SIZE_MAX 4194304 0 0.00 TCP_SEND_SIZE_MIN 4096 0 0.00 USER_TIME 6618 1459 24.32
V$SYS_TIME_MODEL delta values (60 second capture) with unset filesystemio_options during the index scan operation:
STAT_NAME DELTADELTA_SEC
-------------------------------------------------- ----------- ------------ DB CPU 21543721 359062.02 DB time 22548982 375816.37 Java execution elapsed time 0 0.00 PL/SQL compilation elapsed time 179573 2992.88 PL/SQL execution elapsed time 210949 3515.82 RMAN cpu time (backup/restore) 0 0.00 background cpu time 184972 3082.87 background elapsed time 482752 8045.87 connection management call elapsed time 52331 872.18 failed parse (out of shared memory) elapsed time 0 0.00 failed parse elapsed time 0 0.00 hard parse (bind mismatch) elapsed time 5838 97.30 hard parse (sharing criteria) elapsed time 49516 825.27 hard parse elapsed time 899229 14987.15 inbound PL/SQL rpc elapsed time 0 0.00 parse time elapsed 1097713 18295.22 repeated bind elapsed time 7553 125.88 sequence load elapsed time 5252 87.53 sql execute elapsed time 22255425370923.75
Test table and index (think of this example as picking up the X or Y
positions of an engine cylinder wall during CMM testing with 32 test
data points per cylinder – the buffer cache is flushed for consistency
and to simulate an infrequently accessed table):
CREATE TABLE T1 (
ID NUMBER,
DESCRIPTION VARCHAR2(80));
INSERT INTO T1
SELECT
CEIL(ABS(SIN(ROWNUM/9.9999)*10000)),
'This is the long description for this number '|| TO_CHAR(CEIL(ABS
(SIN(ROWNUM/9.9999)*10000)))
FROM
(SELECT
ROWNUM RN
FROM
DUAL
CONNECT BY
LEVEL<=10000),
(SELECT
ROWNUM RN
FROM
DUAL
CONNECT BY
LEVEL<=10000);
COMMIT;
CREATE INDEX IND_T1 ON T1(ID);
EXEC DBMS_STATS.GATHER_TABLE_STATS
(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE, METHOD_OPT=>'FOR ALL
COLUMNS SIZE 1')
ANALYZE INDEX IND_T1 VALIDATE STRUCTURE;
Test script:
set linesize 150
set pagesize 2000
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH SHARED_POOL;
SET ARRAYSIZE 100
spool /u01/app/oracle/results/BCHRTestShortNoAsync.txt
SET AUTOTRACE TRACEONLY EXPLAIN
ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=100;
SELECT
ID,
DESCRIPTION
FROM
T1
WHERE
ID BETWEEN 1 AND 400;
ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=5;
SELECT
ID,
DESCRIPTION
FROM
T1
WHERE
ID BETWEEN 1 AND 400;
SET ARRAYSIZE 100
SET AUTOTRACE TRACEONLY STATISTICS
SET TIMING ON
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SESSION SET TRACEFILE_IDENTIFIER='IND_COST_LARGE100';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=100;
SELECT
ID,
DESCRIPTION
FROM
T1
WHERE
ID BETWEEN 1 AND 400;
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SESSION SET TRACEFILE_IDENTIFIER='IND_COST_LARGE5';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=5;
SELECT
ID,
DESCRIPTION
FROM
T1
WHERE
ID BETWEEN 1 AND 400;
spool off
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Received on Sat Sep 05 2009 - 10:28:54 CDT