Path: news.cambrium.nl!textnews.cambrium.nl!feeder1.cambriumusenet.nl!feeder3.cambriumusenet.nl!feed.tweaknews.nl!193.201.147.78.MISMATCH!feeder.news-service.com!postnews.google.com!l34g2000vba.googlegroups.com!not-for-mail
From: Charles Hooper <hooperc2000@yahoo.com>
Newsgroups: comp.databases.oracle.server
Subject: Re: ASSM bug: slow INSERT after uncomitted DELETE
Date: Sat, 8 Aug 2009 08:04:11 -0700 (PDT)
Organization: http://groups.google.com
Lines: 430
Message-ID: <14eac64f-9114-4801-a65a-2a250c8d069f@l34g2000vba.googlegroups.com>
References: <c26d8840-cb87-4390-9249-2b6293ca66f9@u16g2000pru.googlegroups.com> 
 <27de14dd-1d33-461a-ab24-245d026f6abe@v2g2000vbb.googlegroups.com> 
 <e981ba61-6177-46a9-b224-99dba866b68c@k13g2000prh.googlegroups.com>
NNTP-Posting-Host: 205.208.133.217
Mime-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable
X-Trace: posting.google.com 1249743851 26479 127.0.0.1 (8 Aug 2009 15:04:11 GMT)
X-Complaints-To: groups-abuse@google.com
NNTP-Posting-Date: Sat, 8 Aug 2009 15:04:11 +0000 (UTC)
Complaints-To: groups-abuse@google.com
Injection-Info: l34g2000vba.googlegroups.com; posting-host=205.208.133.217; 
 posting-account=xVXeFwkAAAAz3xgWc6VZyjXxx1jx4jb4
User-Agent: G2/1.0
X-HTTP-UserAgent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; WOW64; 
 Trident/4.0; SLCC1; .NET CLR 2.0.50727; Media Center PC 5.0; .NET CLR 
 3.5.21022; .NET CLR 3.5.30729; MDDC; .NET CLR 3.0.30729),gzip(gfe),gzip(gfe)
Xref:  news.cambrium.nl

On Aug 8, 12:42=A0am, ca111026 <ca111...@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/t=
hread/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*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','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*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','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*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','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*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','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*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','123456789*123456789*123456789*123456789*1234567','123456789*123456789*=
123456789*123456789*1234567','123456789*123456789*123456789*123456789*12345=
67','123456789*123456789*123456789*123456789*1234567');
...
)

@c:\insertstatements.sql

DELETE FROM test_assm;


(Session 2)
SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER =3D '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

(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;

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 =3D '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.)
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=3D6G;

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 =3D '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
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 =3D '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 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=3D3541222,e=3D26125284,p=3D54865,cr=3D69793,cu=3D83979,mis=3D0,r=3D1,d=
ep=3D0,og=3D1,plh=3D0,tim=3D314231018338
STAT #1 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D54865 pw=3D0 time=3D0 us)'

EXEC
#2:c=3D171601,e=3D187295,p=3D0,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,dep=3D0,=
og=3D1,plh=3D0,tim=3D314231205633
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D0 pw=3D0 time=3D0 us)'

EXEC
#1:c=3D156001,e=3D155942,p=3D0,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,dep=3D0,=
og=3D1,plh=3D0,tim=3D314231361575
STAT #1 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D0 pw=3D0 time=3D0 us)'

EXEC
#2:c=3D171602,e=3D156113,p=3D0,cr=3D69793,cu=3D83959,mis=3D0,r=3D1,dep=3D0,=
og=3D1,plh=3D0,tim=3D314231517688
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D0 pw=3D0 time=3D0 us)'
------------------

The first couple from yesterday's trace file also with the 6GB KEEP
pool in effect:
EXEC
#3:c=3D3759624,e=3D20904025,p=3D69802,cr=3D69793,cu=3D83979,mis=3D0,r=3D1,d=
ep=3D0,og=3D1,plh=3D0,tim=3D220862828163
STAT #3 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D69802 pw=3D0 time=3D0 us)'

EXEC
#2:c=3D3978025,e=3D15984033,p=3D69802,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,d=
ep=3D0,og=3D1,plh=3D0,tim=3D220878812196
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D69802 pw=3D0 time=3D0 us)'

EXEC
#1:c=3D3666024,e=3D13540824,p=3D69802,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,d=
ep=3D0,og=3D1,plh=3D0,tim=3D220892353020
STAT #1 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D69802 pw=3D0 time=3D0 us)'

EXEC
#3:c=3D3744024,e=3D13634412,p=3D69802,cr=3D69793,cu=3D83959,mis=3D0,r=3D1,d=
ep=3D0,og=3D1,plh=3D0,tim=3D220905987432
STAT #3 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D69802 pw=3D0 time=3D0 us)'

EXEC
#2:c=3D3650423,e=3D13447212,p=3D69803,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,d=
ep=3D0,og=3D1,plh=3D0,tim=3D220919434644
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69793 pr=3D69803 pw=3D0 time=3D0 us)'

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.