28 | January | 2010 | Charles Hooper's Oracle Notes

Database using ASSM Tablespace Exhibits Slow Insert Performance After an Uncommitted Delete

28 01 2010

January 28, 2010 (Updated January 19, 2011)

In August 2009 an interesting test case appeared in the comp.database.oracle.server Usenet group, with a follow-up post in a second thread. The test case that was posted follows:

1. Create tablespace, it uses default 8K block size

create tablespace assm
extent management local uniform size 1m
segment space management auto
datafile
'/abc/db01/oracle/ABC1P/oradata/assm_01.dbf' size 1000m;

2. Create table

create table test_assm
(
 n1 number,
 v1 varchar2(50),
 v2 varchar2(50),
 v3 varchar2(50),
 v4 varchar2(50),
 v5 varchar2(50),
 v6 varchar2(50),
 v7 varchar2(50),
 v8 varchar2(50),
 v9 varchar2(50),
v10 varchar2(50)
)
tablespace assm;

3. Populate table with 1,000,000 rows, COMMIT at the end

begin
for i in 1..1000000 loop
insert into test_assm values
(i,
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567');
end loop;
end;
/

COMMIT;

4. Insert additional 1000 rows into the table using ***SINGLE_ROW*** inserts. I used following script to generate INSERT statements (don’t forget to execute the resulting INSERT statements)

select
'insert into test_assm values(' || n1 ||
',''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'');'
from
        test_assm
where
        rownum < 1001;

It took 1 second to insert 1000 rows through single-row inserts.

5. Delete all rows from the table, don’t commit

6. Re-execute script that inserts 1000 rows from a different session. Runtime > 20 min. There were no indexes on the table.

Insert into table containing uncomitted DELETE should not be significantly slower than insert into table without DELETE.

My test results follow.

I executed the test on 64 bit Windows with a fairly slow disk system (little front end caching from the disk subsystem) running Oracle 11.1.0.7, 8KB block size, with the __DB_CACHE_SIZE currently floating at 0.9375GB due to a much larger DB_KEEP_CACHE_SIZE value. What do I see?

(Edit Jan 19, 2011: Script added to create the c:\insertstatements.sql file)

set linesize 1000
set trimspool on
set pagesize 2000
spool c:\insertstatements.sql

select
'insert into test_assm values(' || n1 ||
',''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'',' ||
'''123456789*123456789*123456789*123456789*1234567'');'
from
        test_assm
where
        rownum < 1001;

spool off

(Remove the creation SQL statement and the header row from the c:\insertstatements.sql file.)

SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME_TEST_ASSM';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

@c:\insertstatements.sql
 
DELETE FROM TEST_ASSM;
 
@c:\insertstatements.sql

1 row created.
Elapsed: 00:00:20.92
1 row created.
Elapsed: 00:00:15.98
1 row created.
Elapsed: 00:00:13.52
1 row created.
...
Elapsed: 00:00:12.41
1 row created.
Elapsed: 00:00:11.84
1 row created.
Elapsed: 00:00:12.32
1 row created.
...

Interesting… becoming faster as more blocks are cached.

So, what is in the trace file?

PARSING IN CURSOR #3 len=532 dep=0 uid=56 oct=2 lid=56 tim=220841924138 hv=471712922 ad='2778b31b8' sqlid='dyqznk8f1vj4u'
insert into test_assm values
  (15,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #3:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220841924138
WAIT #3: nam='db file sequential read' ela= 17613 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220841943750
WAIT #3: nam='db file sequential read' ela= 458 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220841944275
WAIT #3: nam='db file sequential read' ela= 617 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220841944980
WAIT #3: nam='db file sequential read' ela= 73 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220841945113
WAIT #3: nam='db file sequential read' ela= 387 file#=7 block#=1900683 blocks=1 obj#=67153 tim=220841945532
WAIT #3: nam='db file sequential read' ela= 72 file#=7 block#=1900684 blocks=1 obj#=67153 tim=220841945656
WAIT #3: nam='db file sequential read' ela= 14610 file#=7 block#=1900685 blocks=1 obj#=67153 tim=220841960301
...
WAIT #3: nam='db file sequential read' ela= 28 file#=7 block#=1972309 blocks=1 obj#=67153 tim=220862843585
WAIT #3: nam='db file sequential read' ela= 29 file#=7 block#=1972325 blocks=1 obj#=67153 tim=220862843638
WAIT #3: nam='db file sequential read' ela= 69 file#=7 block#=1972341 blocks=1 obj#=67153 tim=220862843732
WAIT #3: nam='db file sequential read' ela= 41 file#=7 block#=1972102 blocks=1 obj#=67153 tim=220862843817
EXEC #3:c=3759624,e=20904025,p=69802,cr=69793,cu=83979,mis=0,r=1,dep=0,og=1,plh=0,tim=220862828163
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=69802 pw=0 time=0 us)'

Looks like a lot of single block reads, some in the range of 0.017613 seconds, others in the range of 0.000028 seconds. A summary of the first insert looks like this:

First Reference: Cursor 3   Ver 1   Parse at 0.000000
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000000|ROWs        0| PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|
|EXECs        1|CPU S    3.759624|CLOCK S   20.904025|ROWs        1| PHY RD BLKs     69802|CON RD BLKs (Mem)     69793|CUR RD BLKs (Mem)     83979|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0| PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|

  CPU S 100.00%  CLOCK S 100.00%
  *   18.032425 seconds of time related data file I/O
  *    0.001392 seconds of time related to client/network events

Wait Event Summary:
db file sequential read            18.032425  On DB Server        Min Wait:     0.000022  Avg Wait:     0.000258  Max Wait:     0.071639
SQL*Net message to client           0.000003  On Client/Network   Min Wait:     0.000003  Avg Wait:     0.000003  Max Wait:     0.000003
SQL*Net message from client         0.001389  On Client/Network   Min Wait:     0.001389  Avg Wait:     0.001389  Max Wait:     0.001389

69,802 physical block reads, 69,793 consistent gets, 83,979 current mode gets, 18.03 seconds spent performing single block reads. This seems to be behaving similar to the bug that Jonathan Lewis found with ASSM 16KB block size tablespaces in 2008 when column values in existing rows were changed from NULL to a value. In that case, the current mode gets were the tipoff that there was a problem.

—

I repeated the test with an ASSM tablespace with 1MB uniform extents. The first insert performed 71,250 physical block reads, 71,206 consistent gets, 85,473 current mode gets, 18.85 seconds performing single block reads with an elapsed time of 21.53 and for some reason 0 CPU seconds (the next insert reported 3.59 CPU seconds).

I also repeated the test with a locally managed table with with 1MB uniform extents without ASSM: “SIZE 2G REUSE AUTOEXTEND ON NEXT 10M MAXSIZE UNLIMITED LOGGING EXTENT MANAGEMENT LOCAL UNIFORM SIZE 1M SEGMENT SPACE MANAGEMENT MANUAL”. The results in the final test were a little disappointing. The totals from the script execution for all of the inserts:

Total for Trace File:
|PARSEs    1003|CPU S    0.234002|CLOCK S    0.312034|ROWs        0| PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|
|EXECs     1003|CPU S    0.031200|CLOCK S    0.062434|ROWs     1002| PHY RD BLKs         0|CON RD BLKs (Mem)      1051|CUR RD BLKs (Mem)      1343|
|FETCHs       2|CPU S    0.000000|CLOCK S    0.000000|ROWs        1| PHY RD BLKs         0|CON RD BLKs (Mem)         3|CUR RD BLKs (Mem)         0|

Wait Event Summary:
SQL*Net message to client           0.001472  On Client/Network   Min Wait:     0.000001  Avg Wait:     0.000001  Max Wait:     0.000076
SQL*Net message from client         0.683966  On Client/Network   Min Wait:     0.000402  Avg Wait:     0.000684  Max Wait:     0.001799

The totals for all of the inserts performed 0 physical block reads, 1,051 consistent gets, 1,343 current mode gets, 0 seconds performing single block reads with an elapsed time of 0.374468 seconds (0.312034 of that was for parsing) and 0.265202 CPU seconds (0.234002 of that for parsing).

—

A couple of additional tests, since some of the posters in the Usenet thread reported different behavior.

CREATE SMALLFILE TABLESPACE "LOCAL_UNIFORM1M" DATAFILE 'C:\ORACLE\ORADATA\OR11\locun1MOR1101.dbf' SIZE 2G REUSE AUTOEXTEND ON NEXT 10M
    MAXSIZE UNLIMITED LOGGING EXTENT MANAGEMENT LOCAL UNIFORM SIZE 1M SEGMENT SPACE MANAGEMENT MANUAL;

CREATE SMALLFILE TABLESPACE "LOCAL_ASSM" LOGGING DATAFILE 'C:\Oracle\OraData\OR11\locassmOR1101.dbf' SIZE 2G REUSE AUTOEXTEND ON NEXT 10M
    MAXSIZE UNLIMITED EXTENT MANAGEMENT LOCAL SEGMENT SPACE MANAGEMENT AUTO;

SELECT
  TABLESPACE_NAME,
  BLOCK_SIZE,
  ALLOCATION_TYPE,SEGMENT_SPACE_MANAGEMENT,EXTENT_MANAGEMENT
FROM DBA_TABLESPACES;

TABLESPACE_NAME BLOCK_SIZE ALLOCATIO SEGMEN EXTENT_MAN
--------------- ---------- --------- ------ ----------
LOCAL_UNIFORM1M       8192 UNIFORM   MANUAL LOCAL
LOCAL_ASSM            8192 SYSTEM    AUTO   LOCAL

We now have a new locally managed tablespace with 1MB extents not using ASSM, and another new tablespace using ASSM with autoallocated extents (my original test used an old ASSM autoallocate tablespace containing other data).

(Session 1)

create table test_assm
(
 n1 number,
 v1 varchar2(50),
 v2 varchar2(50),
 v3 varchar2(50),
 v4 varchar2(50),
 v5 varchar2(50),
 v6 varchar2(50),
 v7 varchar2(50),
 v8 varchar2(50),
 v9 varchar2(50),
v10 varchar2(50)
)
tablespace LOCAL_UNIFORM1M;

begin
for i in 1..1000000 loop
insert into test_assm values
(i,
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567');
end loop;
end;
/

COMMIT;

Build the insertstatements.sql file using the select statement provided by the OP, which will include statements like the following:

insert into test_assm values
  (15,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567');
insert into test_assm values
  (16,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567');
insert into test_assm values
  (17,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567');
insert into test_assm values
  (18,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567');
insert into test_assm values
  (19,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567');
...

)

@c:\insertstatements.sql

DELETE FROM test_assm;

(Session 2)

SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME_TEST_LOCAL1UM';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

@c:\insertstatements.sql

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

EXIT

Using the LOCAL_UNIFORM1M tablespace, the insert completed in less than a second.

Reconnect session 2

Repeated the test with the KEEP pool at 1MB, which allowed the default buffer pool to grow:
(Session 1)

DROP TABLE TEST_ASSM PURGE;

create table test_assm
(
 n1 number,
 v1 varchar2(50),
 v2 varchar2(50),
 v3 varchar2(50),
 v4 varchar2(50),
 v5 varchar2(50),
 v6 varchar2(50),
 v7 varchar2(50),
 v8 varchar2(50),
 v9 varchar2(50),
v10 varchar2(50)
)
tablespace LOCAL_ASSM;

begin
for i in 1..1000000 loop
insert into test_assm values
(i,
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567');
end loop;
end;
/

COMMIT;

@c:\insertstatements.sql

DELETE FROM test_assm;

(Session 2)

SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME_TEST_LOCALAM';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

@c:\insertstatements.sql

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

EXIT

Each insert statements reported an elapsed time of 0.14 to 0.15 seconds. __DB_CACHE_SIZE floated to 7,449,083,904

Reconnect session 2

Repeating the test again with a smaller __DB_CACHE_SIZE:
(Session 1)

DROP TABLE TEST_ASSM PURGE;
ALTER SYSTEM SET DB_KEEP_CACHE_SIZE=6G;
create table test_assm
(
 n1 number,
 v1 varchar2(50),
 v2 varchar2(50),
 v3 varchar2(50),
 v4 varchar2(50),
 v5 varchar2(50),
 v6 varchar2(50),
 v7 varchar2(50),
 v8 varchar2(50),
 v9 varchar2(50),
v10 varchar2(50)
)
tablespace LOCAL_ASSM;

begin
for i in 1..1000000 loop
insert into test_assm values
(i,
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567');
end loop;
end;
/

COMMIT;

@c:\insertstatements.sql

DELETE FROM test_assm;

(Session 2)

SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME_TEST_LOCALAM2';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

@c:\insertstatements.sql

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

EXIT

Each insert statement after the first reported an elapsed time of 0.14 to 0.15 seconds. __DB_CACHE_SIZE floated to 1,073,741,824

The execution time was about the same as with the larger __DB_CACHE_SIZE. Apparently only the first insert experienced a large number of ‘db file sequential read’ waits, totalling about 28 seconds based on the timing reported in SQL*Plus.

What if we flood the KEEP and DEFAULT buffer pools:

(Session 3 connected as SYS)

SET LINESIZE 150
SET PAGESIZE 10000
SPOOL C:\TABLES.SQL

SELECT
  'SELECT * FROM '||OWNER||'.'||TABLE_NAME||' ORDER BY 1;' T
FROM
  DBA_TABLES;

SPOOL OFF

Clean up the C:\TABLES.SQL file.

SET AUTOTRACE TRACEONLY STATISTICS;

@C:\TABLES.SQL

SET AUTOTRACE OFF

(Session 1)

DROP TABLE TEST_ASSM PURGE;

create table test_assm
(
 n1 number,
 v1 varchar2(50),
 v2 varchar2(50),
 v3 varchar2(50),
 v4 varchar2(50),
 v5 varchar2(50),
 v6 varchar2(50),
 v7 varchar2(50),
 v8 varchar2(50),
 v9 varchar2(50),
v10 varchar2(50)
)
tablespace LOCAL_ASSM;

begin
for i in 1..1000000 loop
insert into test_assm values
(i,
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567',
'123456789*123456789*123456789*123456789*1234567');
end loop;
end;
/

COMMIT;

@c:\insertstatements.sql

DELETE FROM test_assm;

(Session 2)

SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME_TEST_LOCALAM3';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

@c:\insertstatements.sql

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

EXIT

Each insert statement after the first reported an elapsed time of 0.17 to 0.19 seconds. OK, that increased the time slightly, but not as much seen earlier.

Maybe it has to due with the process ID – luck of the draw regarding which blocks session 2 attempts to insert into due to the way ASSM attempts to reduce block contention? I repeated the test again using the same old ASSM tablespace which I used earlier – insert times for the second session where roughly 0.15 seconds each after the first insert completed. Of course, I bounced the database since the test run the day before, so maybe that has an impact?

The first couple of EXEC and STAT lines from the first of the most recent traces with the 6GB KEEP pool in effect:

EXEC #1:c=3541222,e=26125284,p=54865,cr=69793,cu=83979,mis=0,r=1,dep=0,og=1,plh=0,tim=314231018338
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=54865 pw=0 time=0 us)'
EXEC #2:c=171601,e=187295,p=0,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=314231205633
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=0 pw=0 time=0 us)'
EXEC #1:c=156001,e=155942,p=0,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=314231361575
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=0 pw=0 time=0 us)'
EXEC #2:c=171602,e=156113,p=0,cr=69793,cu=83959,mis=0,r=1,dep=0,og=1,plh=0,tim=314231517688
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=0 pw=0 time=0 us)'

The first couple of lines from the previous day’s trace file also with the 6GB KEEP pool in effect:

EXEC #3:c=3759624,e=20904025,p=69802,cr=69793,cu=83979,mis=0,r=1,dep=0,og=1,plh=0,tim=220862828163
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=69802 pw=0 time=0 us)'
EXEC #2:c=3978025,e=15984033,p=69802,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=220878812196
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=69802 pw=0 time=0 us)'
EXEC #1:c=3666024,e=13540824,p=69802,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=220892353020
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=69802 pw=0 time=0 us)'
EXEC #3:c=3744024,e=13634412,p=69802,cr=69793,cu=83959,mis=0,r=1,dep=0,og=1,plh=0,tim=220905987432
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=69802 pw=0 time=0 us)'
EXEC #2:c=3650423,e=13447212,p=69803,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=220919434644
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=69803 pw=0 time=0 us)'

—

This is partial output from the 10046 trace file captured yesterday and today, which targetted a pre-existing ASSM tablespace with roughly the same size default buffer cache in effect (note that the database was bounced between runs, and that may be a source of the time difference).
Yesterday:

PARSING IN CURSOR #3 len=532 dep=0 uid=56 oct=2 lid=56 tim=220841924138 hv=471712922 ad='2778b31b8' sqlid='dyqznk8f1vj4u'
insert into test_assm values
  (15,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #3:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220841924138
WAIT #3: nam='db file sequential read' ela= 17613 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220841943750
WAIT #3: nam='db file sequential read' ela= 458 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220841944275
WAIT #3: nam='db file sequential read' ela= 617 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220841944980
WAIT #3: nam='db file sequential read' ela= 73 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220841945113
...
PARSING IN CURSOR #2 len=532 dep=0 uid=56 oct=2 lid=56 tim=220862828163 hv=1479200138 ad='2778aa958' sqlid='6su1s3tc2pmca'
insert into test_assm values
  (16,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220862828163
WAIT #2: nam='db file sequential read' ela= 4517 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220862850571
WAIT #2: nam='db file sequential read' ela= 484 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220862851087
WAIT #2: nam='db file sequential read' ela= 548 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220862851684
WAIT #2: nam='db file sequential read' ela= 33 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220862851760
...
PARSING IN CURSOR #1 len=532 dep=0 uid=56 oct=2 lid=56 tim=220878812196 hv=3933466223 ad='2737d43f8' sqlid='g6dd19gp77vmg'
insert into test_assm values
  (17,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220878812196
WAIT #1: nam='db file sequential read' ela= 8169 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220878847836
WAIT #1: nam='db file sequential read' ela= 470 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220878848364
WAIT #1: nam='db file sequential read' ela= 510 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220878848923
WAIT #1: nam='db file sequential read' ela= 37 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220878849003
...
PARSING IN CURSOR #3 len=532 dep=0 uid=56 oct=2 lid=56 tim=220892353020 hv=1578030285 ad='273749f28' sqlid='a7tcr1tg0xp6d'
insert into test_assm values
  (18,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #3:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220892353020
WAIT #3: nam='db file sequential read' ela= 6309 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220892365476
WAIT #3: nam='db file sequential read' ela= 507 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220892366027
WAIT #3: nam='db file sequential read' ela= 476 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220892366551
WAIT #3: nam='db file sequential read' ela= 37 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220892366630
...
PARSING IN CURSOR #2 len=532 dep=0 uid=56 oct=2 lid=56 tim=220905987432 hv=2708362693 ad='2737a1a18' sqlid='7mbckzyhqwpf5'
insert into test_assm values
  (19,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220905987432
WAIT #2: nam='db file sequential read' ela= 7892 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220905999307
WAIT #2: nam='db file sequential read' ela= 513 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220905999847
WAIT #2: nam='db file sequential read' ela= 518 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220906000413
WAIT #2: nam='db file sequential read' ela= 37 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220906000493
...
PARSING IN CURSOR #1 len=532 dep=0 uid=56 oct=2 lid=56 tim=220919434644 hv=3773067906 ad='2778aa2c8' sqlid='4gsb2p3hf8wn2'
insert into test_assm values
  (20,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=220919434644
WAIT #1: nam='db file sequential read' ela= 4513 file#=7 block#=1900672 blocks=1 obj#=67153 tim=220919467246
WAIT #1: nam='db file sequential read' ela= 483 file#=7 block#=1900680 blocks=1 obj#=67153 tim=220919467788
WAIT #1: nam='db file sequential read' ela= 474 file#=7 block#=1900681 blocks=1 obj#=67153 tim=220919468320
WAIT #1: nam='db file sequential read' ela= 45 file#=7 block#=1900682 blocks=1 obj#=67153 tim=220919468416

—

Today, same tablespace, roughly the same default buffer size:

PARSING IN CURSOR #2 len=532 dep=0 uid=56 oct=2 lid=56 tim=314564780904 hv=471712922 ad='2772d7f28' sqlid='dyqznk8f1vj4u'
insert into test_assm values
  (15,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=314564780904
WAIT #2: nam='db file sequential read' ela= 12462 file#=7 block#=1901256 blocks=1 obj#=67277 tim=314564795862
WAIT #2: nam='db file sequential read' ela= 531 file#=7 block#=1901257 blocks=1 obj#=67277 tim=314564796472
WAIT #2: nam='db file sequential read' ela= 72 file#=7 block#=1901258 blocks=1 obj#=67277 tim=314564796577
WAIT #2: nam='db file sequential read' ela= 331 file#=7 block#=1901259 blocks=1 obj#=67277 tim=314564796941
...
PARSING IN CURSOR #1 len=532 dep=0 uid=56 oct=2 lid=56 tim=314585990954 hv=1479200138 ad='2772d7a28' sqlid='6su1s3tc2pmca'
insert into test_assm values
  (16,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=314585990954
EXEC #1:c=156001,e=156030,p=0,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=314586146984
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=0 pw=0 time=0 us)'
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=67277 tim=314586149201
WAIT #1: nam='SQL*Net message from client' ela= 1674 driver id=1413697536 #bytes=1 p3=0 obj#=67277 tim=314586150901
CLOSE #1:c=0,e=0,dep=0,type=0,tim=314586146984
PARSING IN CURSOR #2 len=532 dep=0 uid=56 oct=2 lid=56 tim=314586146984 hv=3933466223 ad='2734efe38' sqlid='g6dd19gp77vmg'
insert into test_assm values
  (17,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=314586146984
EXEC #2:c=140401,e=124827,p=0,cr=69793,cu=83958,mis=0,r=1,dep=0,og=1,plh=0,tim=314586271811
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69793 pr=0 pw=0 time=0 us)'
WAIT #2: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=67277 tim=314586294069
WAIT #2: nam='SQL*Net message from client' ela= 1347 driver id=1413697536 #bytes=1 p3=0 obj#=67277 tim=314586295442
CLOSE #2:c=0,e=0,dep=0,type=0,tim=314586271811
...

(A bit later in the trace):

PARSING IN CURSOR #2 len=533 dep=0 uid=56 oct=2 lid=56 tim=314624211019 hv=1207345385 ad='2734b6ff8' sqlid='15mbakd3zd879'
insert into test_assm values
  (239,'123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567',
  '123456789*123456789*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=314624211019
WAIT #2: nam='db file sequential read' ela= 519 file#=7 block#=1972923 blocks=1 obj#=67277 tim=314624366489
EXEC #2:c=140401,e=124781,p=1,cr=69794,cu=83960,mis=0,r=1,dep=0,og=1,plh=0,tim=314624335800
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=69794 pr=1 pw=0 time=0 us)'
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=67277 tim=314624366655
WAIT #2: nam='SQL*Net message from client' ela= 814 driver id=1413697536 #bytes=1 p3=0 obj#=67277 tim=314624367493
CLOSE #2:c=0,e=0,dep=0,type=0,tim=314624367010

In yesterday’s run, Oracle kept performing single block reads on exactly the same blocks for each insert statement (additional blocks were added one at a time on later inserts). Today this only happened for the first insert statement, with occasional single block reads after that point.

Jonathan had commented somewhere that ASSM is like freelists(16) (or maybe it was freelist groups (16)). The blocks selected for insert are dependent on the v$process.pid for the session (I have seen a couple of good descriptions of how this works, but cannot locate those descriptions right now). See the follow up to comment 10 here:
http://jonathanlewis.wordpress.com/2009/01/14/books/

I suspect that this might have something to do with the problem I experienced yesterday, but not today (which free blocks are available to the session).

In this link, there are a couple of posts which describe this, or a similar problem:
asktom.oracle.com Article 1
(April 24, 2003 by Jan van Mourik)
(December 21, 2004 by Steve)

asktom.oracle.com Article 2
(December 4, 2005 by Jonathan Lewis)

On December 24, 2008 a thread was started on Oracle’s OTN forums titled “Performance degradation of repeated delete/inserts” that seems to describe a similar problem. The thread has since disappeared from Oracle’s OTN forums. In that thread someone told me “YOU CANNOT PROVE ANYTHING ABOUT ORACLE PERFORMANCE. EVER. NO EQUATIONS, NO PROOFS, NO WAY, NO HOW…“. I think that it was comments like this that eventually contributed to the thread being pulled from the OTN forums.

I believe that this blog article and the contents of the two Usenet threads demonstrates the potential value of test cases.

——————————————————

Take some time to read the two Usenet threads. I think that you will find that Jonathan Lewis and other contributors were able to identify the root cause of the performance difference between the tests with the ASSM and non-ASSM tablespaces.

Comments : 1 Comment »

Categories : Performance

	Charles Hooper on Favorite Free Applications to…
	Zach on Favorite Free Applications to…
	Charles Hooper on Favorite Free Applications to…
	Zach on Favorite Free Applications to…
	Charles Hooper on Huge Presentation – Work…
	Dan on Huge Presentation – Work…
	Charles Hooper on Review of Synology DS415+, How…
	Matthias Clausen on Review of Synology DS415+, How…
	Charles Hooper on _SMALL_TABLE_THRESHOLD Paramet…
	mohd atif on _SMALL_TABLE_THRESHOLD Paramet…
	Charles Hooper on Free ANSI SQL to Oracle Specif…
	Kalin Agrawal on Free ANSI SQL to Oracle Specif…
	Charles Hooper on Large Page Support or Not…
	vaurob on Large Page Support or Not…
	Locating Oracle… on Finding a New Home for a Clien…

Charles Hooper's Oracle Notes

Database using ASSM Tablespace Exhibits Slow Insert Performance After an Uncommitted Delete

Categories

Recent Articles

Misc. Articles

Popular Articles

Recent Comments

Blogroll

Hints for Posting Code Sections in Comments