Re: Surprising Performance Changes with Oracle 11.2.0.1 (Long Post)

From: Charles Hooper <hooperc2000_at_yahoo.com>
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:04am, "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=19
requests=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=19
requests=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                                                DELTA
DELTA_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                              39621673
660361.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                                                DELTA
DELTA_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                               9611995
160199.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                                                DELTA
DELTA_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                              22255425
370923.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

Original text of this message