Re: Why such high buffer gets for a simple insert and inconsistent in every run

  • From: kunwar singh <krishsingh.111@xxxxxxxxx>
  • To: Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
  • Date: Wed, 8 Aug 2018 06:58:49 -0400

Thanks a lot Jonathan for the explanation! I have understood it well now.

On Tue, Aug 7, 2018 at 6:14 AM, Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
wrote:


At the level of inserting one row into a very small table with one index
it's hard to determine by trial and error what the buffer visits are, but
if you enable sql trace and check the PARSE# and EXEC# lines you may see
that generally you get "cr=3" on the parse, and "cr=1, cu=5" on the exec.
(That's what I get on 12.1.0.2).  If you repeat the execution of the
statement the PARSE# line drops to cr=0, which is why you get very close to
an average of 6 buffer gets per execute after repeating the insert of 1114.

Without access to a sytem running dtrace (or similarly low-level
mechanism) I don't think it's possible to dump details of the current block
gets, and the 10200 range of trace events are only about consistent gets,
so we can only guess which blocks are being accessed.  Bear in mind,
though, the following:

To insert a row in ASSM you need to find a block with free space.
Starting from cold you need to:

1) Access the segment header, then a level 2 bitmap, then a level 1 bitmap
to find a block.  (3 buffer gets)
2) get the table block in currrent mode to modify it, possibly get an undo
block to do some block cleanout, create an undo entry in an undo block,
3) get the index block in current mode (and maybe consistent mode as well
for a unique index so that you don't try to create a duplicate of a row
that existed when your insert began), possibly get an undo block to do some
block cleanout, create an undo entry in an undo block

Possibly the parse call is where the space management access takes place,
and possibly the blocks stay pinned when you keep the cursor open by
repeating it (test the idea by setting open_cursors to zero and
session_cached_cursors to zero and see if the numbers change) - this may
explain the disappearance of the cr=3 on PARSE#. You may also see a small
effect depending on whether you have set serveroutput on or off - another
thing for you to test, I don't know whether it will or not.

If you want to follow up the dtrace idea then Alexander Anokhin produced a
useful tool a few years ago:  https://alexanderanokhin.com/
2011/11/13/dynamic-tracing-of-oracle-logical-io/

Regards
Jonathan Lewis

________________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on
behalf of kunwar singh <krishsingh.111@xxxxxxxxx>
Sent: 05 August 2018 17:24:25
To: sachin pawar
Cc: oracle-l@xxxxxxxxxxxxx
Subject: Re: Why such high buffer gets for a simple insert and
inconsistent in every run

Hi Sachin,
Thank you for replying!

- I just ran that trace. it didnt trace anything.

ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
insert into emp values(1114,'TESTEMP3','MANAGER',7839,sysdate,100,100,20);

But the trace file doesnt show any new information compared to what a
normal 10046 trace would show.
Am i doing something wrong?


-Yes i did review that post . x$kcbsw dont have all columns referenced in
the view.  He did mention at the end of the note: that  the two x$
structures( i believe x$kcbsw , x$kcbwh )are not updated in the same way in
11g. So not sure if procedure can be used for this purpose in 12c.

-Yes i already did that before posting here.

Cheers,
Kunwar


On Sun, Aug 5, 2018 at 12:17 PM, sachin pawar <getsach@xxxxxxxxx<mailto:
getsach@xxxxxxxxx>> wrote:
hi Kunwar,

-Did you try tracing with 10200 event?
I have never used but saw it in few posts after google on it.

-Did you review this post from Jonathan Lewis?
http://www.jlcomp.demon.co.uk/buffer_usage.html
note: Not sure if still works for 12c because x$kcbsw structure has
changed , but you can go through it anyways.

-How about searching on MOS for troubleshooting it?
i quickly searched but no exact hits to suggest to you .

Rgds,
Sachin
https://twitter.com/sach_pwr




On Sun, Aug 5, 2018 at 12:07 PM, kunwar singh <krishsingh.111@xxxxxxxxx<
mailto:krishsingh.111@xxxxxxxxx>> wrote:
Hello Performance Experts,

I always thought simple insert ( table doesnt have a LOB)  would always
return very few buffer gets ( if only 1 index on the table) . But below
testcase shows 9 or 11 buffer gets everytime i insert these records . If i
keep on repeating the same inserts it drops to ~6 gets/exec.
Can anyone tell why this is the case? I always thought it would be 3
gets/exec for every execution in such a simple insert into and single index
table.

Version:12.1.0.1.0

TESTCASE:
++++++ ++++++ ++++++
13:48:51 SQL> alter system flush shared_pool;
System altered.
Elapsed: 00:00:00.04
13:48:55 SQL> alter system flush buffer_cache;
System altered.
Elapsed: 00:00:00.17
13:49:03 SQL> create index emp_ix on emp(empno);
Index created.
Elapsed: 00:00:00.16
13:49:08 SQL> exec dbms_stats.gather_table_stats(user, upper('EMP'),
null, method_opt=>'FOR TABLE FOR ALL COLUMNS SIZE REPEAT', cascade=>true);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.92
select *from user_tables where table_name='EMP'
============================================================
====================
TABLE_NAME                     --> EMP
TABLESPACE_NAME                --> USERS
CLUSTER_NAME                   -->
IOT_NAME                       -->
STATUS                         --> VALID
PCT_FREE                       --> 10
PCT_USED                       -->
INI_TRANS                      --> 1
MAX_TRANS                      --> 255
INITIAL_EXTENT                 --> 65536
NEXT_EXTENT                    --> 1048576
MIN_EXTENTS                    --> 1
MAX_EXTENTS                    --> 2147483645
PCT_INCREASE                   -->
FREELISTS                      -->
FREELIST_GROUPS                -->
LOGGING                        --> YES
BACKED_UP                      --> N
NUM_ROWS                       --> 14
BLOCKS                         --> 5
EMPTY_BLOCKS                   --> 0
AVG_SPACE                      --> 0
CHAIN_CNT                      --> 0
AVG_ROW_LEN                    --> 38
AVG_SPACE_FREELIST_BLOCKS      --> 0
NUM_FREELIST_BLOCKS            --> 0
DEGREE                         -->          1
INSTANCES                      -->          1
CACHE                          -->     N
TABLE_LOCK                     --> ENABLED
SAMPLE_SIZE                    --> 14
LAST_ANALYZED                  --> 05-AUG-18
PARTITIONED                    --> NO
IOT_TYPE                       -->
TEMPORARY                      --> N
SECONDARY                      --> N
NESTED                         --> NO
BUFFER_POOL                    --> DEFAULT
FLASH_CACHE                    --> DEFAULT
CELL_FLASH_CACHE               --> DEFAULT
ROW_MOVEMENT                   --> DISABLED
GLOBAL_STATS                   --> YES
USER_STATS                     --> NO
DURATION                       -->
SKIP_CORRUPT                   --> DISABLED
MONITORING                     --> YES
CLUSTER_OWNER                  -->
DEPENDENCIES                   --> DISABLED
COMPRESSION                    --> DISABLED
COMPRESS_FOR                   -->
DROPPED                        --> NO
READ_ONLY                      --> NO
SEGMENT_CREATED                --> YES
RESULT_CACHE                   --> DEFAULT
CLUSTERING                     --> NO
ACTIVITY_TRACKING              -->
DML_TIMESTAMP                  -->
HAS_IDENTITY                   --> NO
CONTAINER_DATA                 --> NO
select *from user_indexes where index_name='EMP_IX'
============================================================
====================
INDEX_NAME                     --> EMP_IX
INDEX_TYPE                     --> NORMAL
TABLE_OWNER                    --> TEST
TABLE_NAME                     --> EMP
TABLE_TYPE                     --> TABLE
UNIQUENESS                     --> NONUNIQUE
COMPRESSION                    --> DISABLED
PREFIX_LENGTH                  -->
TABLESPACE_NAME                --> USERS
INI_TRANS                      --> 2
MAX_TRANS                      --> 255
INITIAL_EXTENT                 --> 65536
NEXT_EXTENT                    --> 1048576
MIN_EXTENTS                    --> 1
MAX_EXTENTS                    --> 2147483645
PCT_INCREASE                   -->
PCT_THRESHOLD                  -->
INCLUDE_COLUMN                 -->
FREELISTS                      -->
FREELIST_GROUPS                -->
PCT_FREE                       --> 10
LOGGING                        --> YES
BLEVEL                         --> 0
LEAF_BLOCKS                    --> 1
DISTINCT_KEYS                  --> 14
AVG_LEAF_BLOCKS_PER_KEY        --> 1
AVG_DATA_BLOCKS_PER_KEY        --> 1
CLUSTERING_FACTOR              --> 1
STATUS                         --> VALID
NUM_ROWS                       --> 14
SAMPLE_SIZE                    --> 14
LAST_ANALYZED                  --> 05-AUG-18
DEGREE                         --> 1
INSTANCES                      --> 1
PARTITIONED                    --> NO
TEMPORARY                      --> N
GENERATED                      --> N
SECONDARY                      --> N
BUFFER_POOL                    --> DEFAULT
FLASH_CACHE                    --> DEFAULT
CELL_FLASH_CACHE               --> DEFAULT
USER_STATS                     --> NO
DURATION                       -->
PCT_DIRECT_ACCESS              -->
ITYP_OWNER                     -->
ITYP_NAME                      -->
PARAMETERS                     -->
GLOBAL_STATS                   --> YES
DOMIDX_STATUS                  -->
DOMIDX_OPSTATUS                -->
FUNCIDX_STATUS                 -->
JOIN_INDEX                     --> NO
IOT_REDUNDANT_PKEY_ELIM        --> NO
DROPPED                        --> NO
VISIBILITY                     --> VISIBLE
DOMIDX_MANAGEMENT              -->
SEGMENT_CREATED                --> YES
ORPHANED_ENTRIES               --> NO
INDEXING                       --> FULL
14:27:49 SQL> insert into emp values(1111,'TESTEMP2','
MANAGER',7839,sysdate,100,100,20);
1 row created.

14:30:45 SQL> select executions,buffer_gets,last_load_time,last_active_time
,sql_text from v$sql where sql_id='77byu2419ywqu';

      Exec|         Gets|LAST_LOAD_TIME                |LAST_ACTIVE_TIME
|SQL Text
----------|-------------|------------------------------|----
--------------|---------------------------------------------
-----------------------------------
         1|           70|2018-08-05/14:28:13           |05-AUG-18
14:28:13|insert into emp values(1111,'TESTEMP2','
MANAGER',7839,sysdate,100,100,20)

14:31:26 SQL> insert into emp values(1112,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20);
1 row created.
14:31:52 SQL> select executions,buffer_gets,last_load_time,last_active_time
,sql_text from v$sql where sql_id='btq8j18jtvk1f';
      Exec|         Gets|LAST_LOAD_TIME                |LAST_ACTIVE_TIME
|SQL Text
----------|-------------|------------------------------|----
--------------|---------------------------------------------
-----------------------------------
         1|           11|2018-08-05/14:31:40           |05-AUG-18
14:31:40|insert into emp values(1112,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20)
14:32:05 SQL> insert into emp values(1113,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20);
1 row created.


14:33:42 SQL> select executions,buffer_gets,last_load_time,last_active_time
,sql_text from v$sql where sql_id='1pa70cs8zdx24';
      Exec|         Gets|LAST_LOAD_TIME                |LAST_ACTIVE_TIME
|SQL Text
----------|-------------|------------------------------|----
--------------|---------------------------------------------
-----------------------------------
         1|            9|2018-08-05/14:32:35           |05-AUG-18
14:32:35|insert into emp values(1113,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20)
1 row selected.
14:32:57 SQL> insert into emp values(1114,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20);
1 row created.
14:34:04 SQL>  select executions,buffer_gets,last_load_time,last_active_time
,sql_text from v$sql where sql_id='g59gcpjybxc7b';
      Exec|         Gets|LAST_LOAD_TIME                |LAST_ACTIVE_TIME
|SQL Text
----------|-------------|------------------------------|----
--------------|---------------------------------------------
-----------------------------------
         1|           11|2018-08-05/14:33:32           |05-AUG-18
14:33:32|insert into emp values(1114,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20)

14:34:13 SQL> select *from v$version;
BANNER
      |    CON_ID
------------------------------------------------------------
--------------------|----------
Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit
Production    |         0
PL/SQL Release 12.1.0.1.0 - Production
      |         0
CORE    12.1.0.1.0      Production
              |         0
TNS for Linux: Version 12.1.0.1.0 - Production
      |         0
NLSRTL Version 12.1.0.1.0 - Production
      |         0


----after thousands of inserts for empno =1114, gets/exec approx 6.
      Exec|         Gets|LAST_LOAD_TIME                |LAST_ACTIVE_TIME
            |SQL_TEXT
----------|-------------|------------------------------|----
--------------------------|---------------------------------
-------------------------------------------------------------------
      2029|        12711|2018-08-05/14:56:22           |05-AUG-18
14:59:24            | insert into emp values(1114,'TESTEMP3','
MANAGER',7839,sysdate,100,100,20)
--- here are the fresh stats after gathering them again:
select *from user_indexes where index_name='EMP_IX'
============================================================
====================
INDEX_NAME                     --> EMP_IX
INDEX_TYPE                     --> NORMAL
TABLE_OWNER                    --> TEST
TABLE_NAME                     --> EMP
TABLE_TYPE                     --> TABLE
UNIQUENESS                     --> NONUNIQUE
COMPRESSION                    --> DISABLED
PREFIX_LENGTH                  -->
TABLESPACE_NAME                --> USERS
INI_TRANS                      --> 2
MAX_TRANS                      --> 255
INITIAL_EXTENT                 --> 65536
NEXT_EXTENT                    --> 1048576
MIN_EXTENTS                    --> 1
MAX_EXTENTS                    --> 2147483645
PCT_INCREASE                   -->
PCT_THRESHOLD                  -->
INCLUDE_COLUMN                 -->
FREELISTS                      -->
FREELIST_GROUPS                -->
PCT_FREE                       --> 10
LOGGING                        --> YES
BLEVEL                         --> 1
LEAF_BLOCKS                    --> 6
DISTINCT_KEYS                  --> 18
AVG_LEAF_BLOCKS_PER_KEY        --> 1
AVG_DATA_BLOCKS_PER_KEY        --> 1
CLUSTERING_FACTOR              --> 15
STATUS                         --> VALID
NUM_ROWS                       --> 2058
SAMPLE_SIZE                    --> 2058
LAST_ANALYZED                  --> 05-AUG-18 15:01:47
DEGREE                         --> 1
INSTANCES                      --> 1
PARTITIONED                    --> NO
TEMPORARY                      --> N
GENERATED                      --> N
SECONDARY                      --> N
BUFFER_POOL                    --> DEFAULT
FLASH_CACHE                    --> DEFAULT
CELL_FLASH_CACHE               --> DEFAULT
USER_STATS                     --> NO
DURATION                       -->
PCT_DIRECT_ACCESS              -->
ITYP_OWNER                     -->
ITYP_NAME                      -->
PARAMETERS                     -->
GLOBAL_STATS                   --> YES
DOMIDX_STATUS                  -->
DOMIDX_OPSTATUS                -->
FUNCIDX_STATUS                 -->
JOIN_INDEX                     --> NO
IOT_REDUNDANT_PKEY_ELIM        --> NO
DROPPED                        --> NO
VISIBILITY                     --> VISIBLE
DOMIDX_MANAGEMENT              -->
SEGMENT_CREATED                --> YES
ORPHANED_ENTRIES               --> NO
INDEXING                       --> FULL
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.06
select *from user_tables where table_name='EMP'
============================================================
====================
TABLE_NAME                     --> EMP
TABLESPACE_NAME                --> USERS
CLUSTER_NAME                   -->
IOT_NAME                       -->
STATUS                         --> VALID
PCT_FREE                       --> 10
PCT_USED                       -->
INI_TRANS                      --> 1
MAX_TRANS                      --> 255
INITIAL_EXTENT                 --> 65536
NEXT_EXTENT                    --> 1048576
MIN_EXTENTS                    --> 1
MAX_EXTENTS                    --> 2147483645
PCT_INCREASE                   -->
FREELISTS                      -->
FREELIST_GROUPS                -->
LOGGING                        --> YES
BACKED_UP                      --> N
NUM_ROWS                       --> 2058
BLOCKS                         --> 20
EMPTY_BLOCKS                   --> 0
AVG_SPACE                      --> 0
CHAIN_CNT                      --> 0
AVG_ROW_LEN                    --> 42
AVG_SPACE_FREELIST_BLOCKS      --> 0
NUM_FREELIST_BLOCKS            --> 0
DEGREE                         -->          1
INSTANCES                      -->          1
CACHE                          -->     N
TABLE_LOCK                     --> ENABLED
SAMPLE_SIZE                    --> 2058
LAST_ANALYZED                  --> 05-AUG-18 15:01:47
PARTITIONED                    --> NO
IOT_TYPE                       -->
TEMPORARY                      --> N
SECONDARY                      --> N
NESTED                         --> NO
BUFFER_POOL                    --> DEFAULT
FLASH_CACHE                    --> DEFAULT
CELL_FLASH_CACHE               --> DEFAULT
ROW_MOVEMENT                   --> DISABLED
GLOBAL_STATS                   --> YES
USER_STATS                     --> NO
DURATION                       -->
SKIP_CORRUPT                   --> DISABLED
MONITORING                     --> YES
CLUSTER_OWNER                  -->
DEPENDENCIES                   --> DISABLED
COMPRESSION                    --> DISABLED
COMPRESS_FOR                   -->
DROPPED                        --> NO
READ_ONLY                      --> NO
SEGMENT_CREATED                --> YES
RESULT_CACHE                   --> DEFAULT
CLUSTERING                     --> NO
ACTIVITY_TRACKING              -->
DML_TIMESTAMP                  -->
HAS_IDENTITY                   --> NO
CONTAINER_DATA                 --> NO


++++++ ++++++ ++++++
Please let me know if you need any more information in order to understand
this behaviour.

p.s. Pardon my ignorance if i have sent the email in wrong format etc. Any
guidance is appreciated :)


Cheers,
Kunwar




--
Cheers,
Kunwar




-- 
Cheers,
Kunwar

Other related posts: