INSERT slow on ASSM (Doc ID 1263496.1)

Last updated on JULY 21, 2017

Applies to:

Oracle Database - Enterprise Edition - Version 10.2.0.1 to 12.1.0.2 [Release 10.2 to 12.1]
Information in this document applies to any platform.
***Checked for relevance on 21-Jul-2017***

Symptoms

A single INSERT statement following a large batch INSERT is very slow. The second execution of the same INSERT finishes immediately.

The 10046 trace file for the first single slow INSERT shows excessive  waits on 'db file sequential read':

Elapsed times include waiting on following events:
Event waited on                           Times  Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
rdbms ipc reply                               1       0.00         0.00
SQL*Net more data from client                 2       0.00         0.00
db file sequential read                    9670       0.02        13.73
db file scattered read                       56       0.02         0.84
SQL*Net break/reset to client                 1       0.00         0.00


The execution statistics show excessive values for 'db block gets':

Statistics
----------------------------------------------------------
1 recursive calls
46272 db block gets
13 consistent gets
21101 physical reads
2937940 redo size
1123 bytes sent via SQL*Net to client
1631 bytes received via SQL*Net from client
4 SQL*Net roundtrips to/from client
1 sorts (memory)
0 sorts (disk)
1 rows processed


The statistics for the second execution of the same INSERT shows low values for 'db block gets':

Statistics
----------------------------------------------------------
0 recursive calls
5 db block gets
1 consistent gets
1 physical reads
0 redo size
1134 bytes sent via SQL*Net to client
1631 bytes received via SQL*Net from client
4 SQL*Net roundtrips to/from client
1 sorts (memory)
0 sorts (disk)
1 rows processed



Using the DBMS_SPACE.UNUSED_SPACE as listed below shows that the FS1 blocks before the first INSERT move to the FULL blocks following the slow execution:

create or replace procedure get_space_info is
total_bl NUMBER;
total_by NUMBER;
unused_bl NUMBER;
unused_by NUMBER;
last_used_extent_file_id NUMBER;
last_used_extent_block_id NUMBER;
last_used_block NUMBER;
unformatted_blocks NUMBER;
unformatted_bytes NUMBER;
fs1_bl NUMBER;
fs1_by NUMBER;
fs2_bl NUMBER;
fs2_by NUMBER;
fs3_bl NUMBER;
fs3_by NUMBER;
fs4_bl NUMBER;
fs4_by NUMBER;
full_bl NUMBER;
full_by NUMBER;
i number;
BEGIN

dbms_space.unused_space('OWNER','TABLE NAME', 'TABLE',
total_bl , total_by , unused_bl , unused_by , last_used_extent_file_id , last_used_extent_block_id , last_used_block );
dbms_space.space_usage('OWNER','TABLE_NAME', 'TABLE',
unformatted_blocks , unformatted_bytes , fs1_bl , fs1_by , fs2_bl , fs2_by , fs3_bl , fs3_by , fs4_bl , fs4_by , full_bl , full_by );

dbms_output.put_line('| total_bl| total_by| unused_bl| unused_by| last_used_extent_file_id| last_used_extent_block_id| last_used_block');
dbms_output.put_line('| '||lpad(total_bl,8)||'|'||
lpad(total_by,9)||'|'||
lpad(unused_bl,10)||'|'||
lpad(unused_by,10)||'|'||
lpad(last_used_extent_file_id,25)||'|'||
lpad(last_used_extent_block_id,26)||'|'||
lpad(last_used_block,16));
dbms_output.put_line(' .');
dbms_output.put_line('| unformatted_blocks| unformatted_bytes| fs1_bl| fs1_by| fs2_bl| fs2_by| fs3_bl| fs3_by| fs4_bl| fs4_by| full_bl| full_by');
dbms_output.put_line('| '||lpad(unformatted_blocks,18)||'|'||
lpad(unformatted_bytes,18)||'|'||
lpad(fs1_bl,7)||'|'||
lpad(fs1_by,7)||'|'||
lpad(fs2_bl,7)||'|'||
lpad(fs2_by,7)||'|'||
lpad(fs3_bl,7)||'|'||
lpad(fs3_by,7)||'|'||
lpad(fs4_bl,7)||'|'||
lpad(fs4_by,7)||'|'||
lpad(full_bl,8)||'|'||
lpad(full_by,8));
end;
/

prompt FS1 means 0-25% free space within a block
prompt FS2 means 25-50% free space within a block
prompt FS3 means 50-75% free space within a block
prompt FS4 means 75-100% free space within a block

set serveroutput on
exec get_space_info;


When tracing the ASSM space allocation during the first single slow INSERT using the following events, the FS1 blocks appear to be marked as FULL:

SQL> ALTER SESSION SET EVENTS '10320 trace name context forever , level 3';
SQL> ALTER SESSION SET EVENTS '10612 trace name context forever , level 1';

SQL> -- run the single INSERT

-- the trace file contains the following comments:

...
[ktspsrch] adddba dba:0x0100636b curl1:0x01006280 curl2:0x01002601
ktspfsrch: Returns: BlockDBA:0x0100637b
kdt_bseg_srch_cbk: examine dba=4.0x0100637b
kdt_bseg_srch_cbk: failed dba=4.0x0100637b avs=837 afs=0 tosp=837 full=1
ktspfupdst: state change tsn 4, objd 96400, objn 71401, blksz 8192
ktspfupdst: oldstate 2, newstate 1, delta bytes 1065
ktspfupdst: fdba: 0x01006280 offset: 251 nblks: 1 newstate: 1
kdt_bseg_srch_cbk: mark full --------------------------------------------------> the blocks is marked as full
ktspfsrch:Cbk didnot like 0x0100637b
...

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms