Path: news.cambrium.nl!textnews.cambrium.nl!feeder8.cambrium.nl!feed.tweaknews.nl!216.40.30.110.MISMATCH!novia!news-out.readnews.com!transit4.readnews.com!postnews.google.com!z28g2000vbl.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 10:55:24 -0700 (PDT)
Organization: http://groups.google.com
Lines: 340
Message-ID: <115e1441-1412-432e-95be-8cbd096bd800@z28g2000vbl.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> 
 <14eac64f-9114-4801-a65a-2a250c8d069f@l34g2000vba.googlegroups.com> 
 <9e338c1d-b399-44bb-957a-ee28eeaeb157@r24g2000vbn.googlegroups.com>
NNTP-Posting-Host: 205.208.133.237
Mime-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable
X-Trace: posting.google.com 1249754125 28769 127.0.0.1 (8 Aug 2009 17:55:25 GMT)
X-Complaints-To: groups-abuse@google.com
NNTP-Posting-Date: Sat, 8 Aug 2009 17:55:25 +0000 (UTC)
Complaints-To: groups-abuse@google.com
Injection-Info: z28g2000vbl.googlegroups.com; posting-host=205.208.133.237; 
 posting-account=xVXeFwkAAAAz3xgWc6VZyjXxx1jx4jb4
User-Agent: G2/1.0
X-HTTP-UserAgent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; 
 Trident/4.0; .NET CLR 1.1.4322),gzip(gfe),gzip(gfe)
Xref:  news.cambrium.nl

On Aug 8, 11:38=A0am, John Hurley <johnbhur...@sbcglobal.net> wrote:
> Charles I got a little lost trying to follow your reply ... sorry.
>
> Wonder if I either screwed something up ( I don't think so ... was
> careful to check tablespace was ASSM and that inserts were in
> different sessions ) or if there is something fixed in 11.1.0.7 in
> linux 64 bit that still has problems on other platforms and/or if the
> fact that my setup is using ASM is also throwing a wrinkle into
> things?
>
> Noons seemed to report that he did not see the same problem either but
> I think that was before the complete test case was posted.

I was not implying that you made a mistake in your test run, I just
saw a couple potential problems with the original test case
description which might cause someone (including myself) to conduct
the test a little different than the OP.  That might include:
* Batching the inserts in the second session, rather than using 1,000
individual SQL statements for the insert.
* Creating the tablespace with the wrong specifications (that happened
to me when I initially tried to set up the tablespace with the 1MB non-
ASSM tablespace - I actually created an ASSM tablespace with 1MB
uniform extents which resulted in roughly the same slow timing as the
ASSM autoallocate tablespace).
* A 10046 trace at level 8 was not set up in the original test case,
which would make it hard to determine where the time was spent.

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=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D220841924138 hv=3D471712922 ad=3D'2778b31b8' sqlid=3D'dyqznk8f1vj4u'
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')
END OF STMT
PARSE
#3:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D220841924138
WAIT #3: nam=3D'db file sequential read' ela=3D 17613 file#=3D7
block#=3D1900672 blocks=3D1 obj#=3D67153 tim=3D220841943750
WAIT #3: nam=3D'db file sequential read' ela=3D 458 file#=3D7 block#=3D1900=
680
blocks=3D1 obj#=3D67153 tim=3D220841944275
WAIT #3: nam=3D'db file sequential read' ela=3D 617 file#=3D7 block#=3D1900=
681
blocks=3D1 obj#=3D67153 tim=3D220841944980
WAIT #3: nam=3D'db file sequential read' ela=3D 73 file#=3D7 block#=3D19006=
82
blocks=3D1 obj#=3D67153 tim=3D220841945113
...
PARSING IN CURSOR #2 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D220862828163 hv=3D1479200138 ad=3D'2778aa958' sqlid=3D'6su1s3tc2pmca'
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')
END OF STMT
PARSE
#2:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D220862828163
WAIT #2: nam=3D'db file sequential read' ela=3D 4517 file#=3D7
block#=3D1900672 blocks=3D1 obj#=3D67153 tim=3D220862850571
WAIT #2: nam=3D'db file sequential read' ela=3D 484 file#=3D7 block#=3D1900=
680
blocks=3D1 obj#=3D67153 tim=3D220862851087
WAIT #2: nam=3D'db file sequential read' ela=3D 548 file#=3D7 block#=3D1900=
681
blocks=3D1 obj#=3D67153 tim=3D220862851684
WAIT #2: nam=3D'db file sequential read' ela=3D 33 file#=3D7 block#=3D19006=
82
blocks=3D1 obj#=3D67153 tim=3D220862851760
...
PARSING IN CURSOR #1 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D220878812196 hv=3D3933466223 ad=3D'2737d43f8' sqlid=3D'g6dd19gp77vmg'
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')
END OF STMT
PARSE
#1:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D220878812196
WAIT #1: nam=3D'db file sequential read' ela=3D 8169 file#=3D7
block#=3D1900672 blocks=3D1 obj#=3D67153 tim=3D220878847836
WAIT #1: nam=3D'db file sequential read' ela=3D 470 file#=3D7 block#=3D1900=
680
blocks=3D1 obj#=3D67153 tim=3D220878848364
WAIT #1: nam=3D'db file sequential read' ela=3D 510 file#=3D7 block#=3D1900=
681
blocks=3D1 obj#=3D67153 tim=3D220878848923
WAIT #1: nam=3D'db file sequential read' ela=3D 37 file#=3D7 block#=3D19006=
82
blocks=3D1 obj#=3D67153 tim=3D220878849003
...
PARSING IN CURSOR #3 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D220892353020 hv=3D1578030285 ad=3D'273749f28' sqlid=3D'a7tcr1tg0xp6d'
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')
END OF STMT
PARSE
#3:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D220892353020
WAIT #3: nam=3D'db file sequential read' ela=3D 6309 file#=3D7
block#=3D1900672 blocks=3D1 obj#=3D67153 tim=3D220892365476
WAIT #3: nam=3D'db file sequential read' ela=3D 507 file#=3D7 block#=3D1900=
680
blocks=3D1 obj#=3D67153 tim=3D220892366027
WAIT #3: nam=3D'db file sequential read' ela=3D 476 file#=3D7 block#=3D1900=
681
blocks=3D1 obj#=3D67153 tim=3D220892366551
WAIT #3: nam=3D'db file sequential read' ela=3D 37 file#=3D7 block#=3D19006=
82
blocks=3D1 obj#=3D67153 tim=3D220892366630
...
PARSING IN CURSOR #2 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D220905987432 hv=3D2708362693 ad=3D'2737a1a18' sqlid=3D'7mbckzyhqwpf5'
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')
END OF STMT
PARSE
#2:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D220905987432
WAIT #2: nam=3D'db file sequential read' ela=3D 7892 file#=3D7
block#=3D1900672 blocks=3D1 obj#=3D67153 tim=3D220905999307
WAIT #2: nam=3D'db file sequential read' ela=3D 513 file#=3D7 block#=3D1900=
680
blocks=3D1 obj#=3D67153 tim=3D220905999847
WAIT #2: nam=3D'db file sequential read' ela=3D 518 file#=3D7 block#=3D1900=
681
blocks=3D1 obj#=3D67153 tim=3D220906000413
WAIT #2: nam=3D'db file sequential read' ela=3D 37 file#=3D7 block#=3D19006=
82
blocks=3D1 obj#=3D67153 tim=3D220906000493
...
PARSING IN CURSOR #1 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D220919434644 hv=3D3773067906 ad=3D'2778aa2c8' sqlid=3D'4gsb2p3hf8wn2'
insert into test_assm values
(20,'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')
END OF STMT
PARSE
#1:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D220919434644
WAIT #1: nam=3D'db file sequential read' ela=3D 4513 file#=3D7
block#=3D1900672 blocks=3D1 obj#=3D67153 tim=3D220919467246
WAIT #1: nam=3D'db file sequential read' ela=3D 483 file#=3D7 block#=3D1900=
680
blocks=3D1 obj#=3D67153 tim=3D220919467788
WAIT #1: nam=3D'db file sequential read' ela=3D 474 file#=3D7 block#=3D1900=
681
blocks=3D1 obj#=3D67153 tim=3D220919468320
WAIT #1: nam=3D'db file sequential read' ela=3D 45 file#=3D7 block#=3D19006=
82
blocks=3D1 obj#=3D67153 tim=3D220919468416

----------------
----------------

Today, same tablespace, roughly the same default buffer size:
PARSING IN CURSOR #2 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D314564780904 hv=3D471712922 ad=3D'2772d7f28' sqlid=3D'dyqznk8f1vj4u'
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')
END OF STMT
PARSE
#2:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D314564780904
WAIT #2: nam=3D'db file sequential read' ela=3D 12462 file#=3D7
block#=3D1901256 blocks=3D1 obj#=3D67277 tim=3D314564795862
WAIT #2: nam=3D'db file sequential read' ela=3D 531 file#=3D7 block#=3D1901=
257
blocks=3D1 obj#=3D67277 tim=3D314564796472
WAIT #2: nam=3D'db file sequential read' ela=3D 72 file#=3D7 block#=3D19012=
58
blocks=3D1 obj#=3D67277 tim=3D314564796577
WAIT #2: nam=3D'db file sequential read' ela=3D 331 file#=3D7 block#=3D1901=
259
blocks=3D1 obj#=3D67277 tim=3D314564796941
...
PARSING IN CURSOR #1 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D314585990954 hv=3D1479200138 ad=3D'2772d7a28' sqlid=3D'6su1s3tc2pmca'
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')
END OF STMT
PARSE
#1:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D314585990954
EXEC
#1:c=3D156001,e=3D156030,p=3D0,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,dep=3D0,=
og=3D1,plh=3D0,tim=3D314586146984
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)'
WAIT #1: nam=3D'SQL*Net message to client' ela=3D 5 driver id=3D1413697536
#bytes=3D1 p3=3D0 obj#=3D67277 tim=3D314586149201
WAIT #1: nam=3D'SQL*Net message from client' ela=3D 1674 driver
id=3D1413697536 #bytes=3D1 p3=3D0 obj#=3D67277 tim=3D314586150901
CLOSE #1:c=3D0,e=3D0,dep=3D0,type=3D0,tim=3D314586146984

PARSING IN CURSOR #2 len=3D532 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D314586146984 hv=3D3933466223 ad=3D'2734efe38' sqlid=3D'g6dd19gp77vmg'
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')
END OF STMT
PARSE
#2:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D314586146984
EXEC
#2:c=3D140401,e=3D124827,p=3D0,cr=3D69793,cu=3D83958,mis=3D0,r=3D1,dep=3D0,=
og=3D1,plh=3D0,tim=3D314586271811
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)'
WAIT #2: nam=3D'SQL*Net message to client' ela=3D 5 driver id=3D1413697536
#bytes=3D1 p3=3D0 obj#=3D67277 tim=3D314586294069
WAIT #2: nam=3D'SQL*Net message from client' ela=3D 1347 driver
id=3D1413697536 #bytes=3D1 p3=3D0 obj#=3D67277 tim=3D314586295442
CLOSE #2:c=3D0,e=3D0,dep=3D0,type=3D0,tim=3D314586271811
...
(A bit later in the trace)
PARSING IN CURSOR #2 len=3D533 dep=3D0 uid=3D56 oct=3D2 lid=3D56
tim=3D314624211019 hv=3D1207345385 ad=3D'2734b6ff8' sqlid=3D'15mbakd3zd879'
insert into test_assm values
(239,'123456789*123456789*123456789*123456789*1234567','123456789*123456789=
*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234=
567','123456789*123456789*123456789*123456789*1234567','123456789*123456789=
*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234=
567','123456789*123456789*123456789*123456789*1234567','123456789*123456789=
*123456789*123456789*1234567','123456789*123456789*123456789*123456789*1234=
567','123456789*123456789*123456789*123456789*1234567')
END OF STMT
PARSE
#2:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D1,plh=3D0,tim=
=3D314624211019
WAIT #2: nam=3D'db file sequential read' ela=3D 519 file#=3D7 block#=3D1972=
923
blocks=3D1 obj#=3D67277 tim=3D314624366489
EXEC
#2:c=3D140401,e=3D124781,p=3D1,cr=3D69794,cu=3D83960,mis=3D0,r=3D1,dep=3D0,=
og=3D1,plh=3D0,tim=3D314624335800
STAT #2 id=3D1 cnt=3D0 pid=3D0 pos=3D1 obj=3D0 op=3D'LOAD TABLE CONVENTIONA=
L
(cr=3D69794 pr=3D1 pw=3D0 time=3D0 us)'
WAIT #2: nam=3D'SQL*Net message to client' ela=3D 2 driver id=3D1413697536
#bytes=3D1 p3=3D0 obj#=3D67277 tim=3D314624366655
WAIT #2: nam=3D'SQL*Net message from client' ela=3D 814 driver
id=3D1413697536 #bytes=3D1 p3=3D0 obj#=3D67277 tim=3D314624367493
CLOSE #2:c=3D0,e=3D0,dep=3D0,type=3D0,tim=3D314624367010

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 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 posts which describe this, or a
similar problem:
http://asktom.oracle.com/pls/asktom/f?p=3D100:11:0::::P11_QUESTION_ID:29294=
12562998
(April 24, 2003 by Jan van Mourik)
(December 21, 2004 by Steve)

http://asktom.oracle.com/pls/asktom/f?p=3D100:11:0::::P11_QUESTION_ID:60202=
71977738
(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" which
seems to describe a similar problem.  It is too bad the thread
disappeared from Oracle's OTN forums.  In that thread Mr. Burleson
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 that which caused the thread to be pulled.

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