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

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_at_gmail.com> 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','MANAGE
>> R',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','MANAGE
>> R',7839,sysdate,100,100,20)
>>
>> 14:31:26 SQL> insert into emp values(1112,'TESTEMP3','MANAGE
>> R',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','MANAGE
>> R',7839,sysdate,100,100,20)
>> 14:32:05 SQL> insert into emp values(1113,'TESTEMP3','MANAGE
>> R',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','MANAGE
>> R',7839,sysdate,100,100,20)
>> 1 row selected.
>> 14:32:57 SQL> insert into emp values(1114,'TESTEMP3','MANAGE
>> R',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','MANAGE
>> R',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','MANAGE
>> R',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
>

--
http://www.freelists.org/webpage/oracle-l