Re: Do you use ASSM (Automatic Segment Space Management)?

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Fri, 7 Aug 2009 06:03:54 -0700 (PDT)
Message-ID: <8be4d60e-3c6d-49ff-b4b2-607afb48252d_at_f33g2000vbm.googlegroups.com>

On Aug 7, 1:04�am, ca111026 <ca111..._at_gmail.com> wrote:
> Test case to reproduceASSMbug: slow inserts when table contains
> large uncomitted DELETE.
>
> Tests were run on AIX 5.3 (64-bit) and Red Hat Linux (32-bit),
> Oracle 10.2.0.4
>
> 1. Create tablespace, it uses default 8K block size
>
> create tablespaceassm
> extentmanagementlocal uniform size 1msegmentspacemanagementauto
> 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)
> )
> tablespaceassm;
>
> 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
>
> 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.

Interesting test case. 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?

SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME_TEST_ASSM'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8'; _at_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 16KB block sizes last year 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.

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc. Received on Fri Aug 07 2009 - 08:03:54 CDT

This message: [ Message body ]
Next message: Preston: "Re: Oracle archive mode and hot backups"
Previous message: Preston: "Re: Oracle archive mode and hot backups"
Maybe in reply to: ca111026: "Do you use ASSM (Automatic Segment Space Management)?"
Next in thread: Charles Hooper: "Re: Do you use ASSM (Automatic Segment Space Management)?"

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

Original text of this message