Trace Files -- 10b : More DML Tracing

In the previous post, I demonstrated what a trace of UPDATE or DELETE would show (or not show).  For example, although Index blocks need to be updated, we cannot identify how many Index blocks were updated.

Let's now look at an INSERT on an empty table and then gradually populate it with single row inserts.

SQL> alter session set deferred_segment_creation=FALSE;

Session altered.

SQL> create table small_insert (id_column number, data_column varchar2(25)) tablespace users;

Table created.

SQL> select blocks from user_segments where segment_name = 'SMALL_INSERT';

    BLOCKS
----------
  8

SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> insert into small_insert select 1, 'Row ONE' from dual;

1 row created.

SQL>


SQL ID: fphypk50c6rtw Plan Hash: 1388734953

insert into small_insert select 1, 'Row ONE' from dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.15          0          1          0           0
Execute      1      0.00       0.00          0          2         30           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.15          0          3         30           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=2 pr=0 pw=0 time=592 us)
         1          1          1   FAST DUAL  (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)

I started with a table with a precreated segment (else the first row INSERT would have had to create the segment).  That count of 30 blocks in current mode is a suprise, isn't it ?  Row Source Operations statistics do not tell us why 30 blocks or which 30 blocks (actually buffers in the buffer cache).
This is from the trace file (not the "cu=30" for the EXEC) :

PARSING IN CURSOR #139944607436728 len=54 dep=0 uid=87 oct=2 lid=87 tim=1450187439148096 hv=1086545724 ad='7f927750' sqlid='fphypk50c6rtw'
insert into small_insert select 1, 'Row ONE' from dual
END OF STMT
PARSE #139944607436728:c=27996,e=331306,p=0,cr=427,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1450187439148091
EXEC #139944607436728:c=1000,e=628,p=0,cr=2,cu=30,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1450187439148770
STAT #139944607436728 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=2 pr=0 pw=0 time=592 us)'
STAT #139944607436728 id=2 cnt=1 pid=1 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)'
WAIT #139944607436728: nam='log file sync' ela= 1652 buffer#=1260 sync scn=4725627 p3=0 obj#=-1 tim=1450187439150552
WAIT #139944607436728: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1450187439150617

Could the 30 blocks be some maintenance operations ?  I leave it to you to conduct your own experiments.  Maybe you could post your findings and observations.
Remember : I have used aggregate=NO and sys=NO in my tkprof calls.
Note that there was no disk read.  The initial table creation with a segment seems to have created the first extent with blocks in the buffer cache (when I do a block dump later, I can confirm that 5 blocks after the segment header are formatted).

Let me do another INSERT.

SQL> insert into small_insert select 2, 'Row TWO' from dual;

1 row created.

SQL>


SQL ID: 9r6zkjh90yvfy Plan Hash: 1388734953

insert into small_insert select 2, 'Row TWO' from dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          1          3           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          1          3           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=118 us)
         1          1          1   FAST DUAL  (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)

I still see 3 blocks in current get mode.  It is quite likely that this second row went into the same block as the first row yet the same block has to be 're-got' in current mode.  Also, an Undo segment block has to be updated.  Note, however, the consistent get also that had to be done.  If we could enable more detailed tracing (can we ?) we might be able to identify which block (buffer in the buffer cache) was in consistent get and which were in current get.

What if I have an index on the table ?

SQL> create index small_insert_ndx on small_insert(id_column);

Index created.

SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> insert into small_insert select 3, 'Row THREE' from dual;

1 row created.

SQL>


SQL ID: cx3ubh9c2r80m Plan Hash: 1388734953

insert into small_insert select 3, 'Row THREE' from dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          1          6           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          1          6           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=223 us)
         1          1          1   FAST DUAL  (cr=0 pr=0 pw=0 time=7 us cost=2 size=0 card=1)

Now we have 6 blocks in current mode.

SQL> insert into small_insert select 4, 'Row FOUR' from dual;

1 row created.

SQL>

insert into small_insert select 4, 'Row FOUR' from dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          1          5           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          1          5           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=206 us)
         1          1          1   FAST DUAL  (cr=0 pr=0 pw=0 time=9 us cost=2 size=0 card=1)

So, with an index present, the current get overhead is greater. Obviously, Oracle has to expend more effort to retrieve and update the index  block.

Here, this table with 4 rows has only 1 table block and 1 index (root) block being used.  The same block is updated for each fresh INSERT, and each call requires a fresh current get.  This means that there will be CPU overhead in repeatedly reading the (same !) block for each fresh INSERT.
Caveat : All 4 rows inserted are inserted by the same session, so they went into the same block.  Had I used different sessions for the 4 rows they may have gone into 2 or more blocks because of the way in which ASSM splits INSERT calls across different blocks.
(Note : A GATHER_TABLE_STATS would show a block count of 5 (not 1, not 8) because the first 5 blocks are formatted, as I can confirm with a block dump).
.
.
.