Re: ASSM bug: slow INSERT after uncomitted DELETE

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Sat, 8 Aug 2009 10:55:24 -0700 (PDT)
Message-ID: <115e1441-1412-432e-95be-8cbd096bd800_at_z28g2000vbl.googlegroups.com>

On Aug 8, 11:38�am, John Hurley <johnbhur..._at_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 nonASSM 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=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 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=100:11:0::::P11_QUESTION_ID:2929412562998
(April 24, 2003 by Jan van Mourik)
(December 21, 2004 by Steve)

http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:6020271977738
(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. Received on Sat Aug 08 2009 - 12:55:24 CDT

This message: [ Message body ]
Next message: Tamkatten_at_gmail.com: "Re: Tested 11g OLTP compression and found rather serious issue"
Previous message: John Hurley: "Re: ASSM bug: slow INSERT after uncomitted DELETE"
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