Re: ASSM bug: slow INSERT after uncomitted DELETE

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Sat, 8 Aug 2009 08:04:11 -0700 (PDT)
Message-ID: <14eac64f-9114-4801-a65a-2a250c8d069f_at_l34g2000vba.googlegroups.com>

On Aug 8, 12:42�am, ca111026 <ca111..._at_gmail.com> wrote:

> Hi John,
>
> Thanks for testing on 11.1.0.7. It is nice to know that they finally
> fixed the bug.

My test in your related thread indicates that the problem may still be present in 11.1.0.7:
http://groups.google.com/group/comp.databases.oracle.server/browse_thread/thread/289b13afe6cf8443

In my test, I saw results which were consistent with what you experienced, which resulted from multiple waits on 'db file sequential read' with sub 1ms access times for each insert in the second session. However, due to the number of 'db file sequential read' waits, a fairly consistent 69,802 per row inserted, each insert required roughly 20 seconds.

John's post made be a bit curious, so I started performing a couple tests.

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 a 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 insertstatements.sql 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'); ...
)

_at_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'; _at_c:\insertstatements.sql
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'; EXIT (All 1000 of the insert statements complete in less than a second.) Reconnect session 2

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

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;

end loop;
end;
/

COMMIT; _at_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'; _at_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.)
Reconnect session 2

__DB_CACHE_SIZE floated to 7,449,083,904

This test run was significantly faster than the test run performed yesterday.

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;

end loop;
end;
/

COMMIT; _at_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'; _at_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
SET AUTOTRACE TRACEONLY STATISTICS;
_at_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;

end loop;
end;
/

COMMIT; _at_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'; _at_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 yesterday.

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 yesterday - 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 yesterday, so maybe that has an impact?

The first couple EXEC and STAT lines from the first trace today 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 from yesterday'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)'

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc. Received on Sat Aug 08 2009 - 10:04:11 CDT

This message: [ Message body ]
Next message: John Hurley: "Re: ASSM bug: slow INSERT after uncomitted DELETE"
Previous message: John Hurley: "Re: Do you use ASSM (Automatic Segment Space Management)?"
Maybe in reply to: ca111026: "ASSM bug: slow INSERT after uncomitted DELETE"
Next in thread: John Hurley: "Re: ASSM bug: slow INSERT after uncomitted DELETE"

Contemporary messages sorted: [ by date ] [ by thread ] [ by subject ] [ by author ]

Original text of this message