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

Wouldn't the touch count in x$bh shed some light on that as well if you carefully craft a test case?

That combined with dumping the blocks should show exactly what's being read.

Stefan

On Wed, 8 Aug 2018, 18:00 kunwar singh, <krishsingh.111_at_gmail.com> wrote:

> 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_at_jlcomp.demon.co.uk> 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_at_freelists.org <oracle-l-bounce_at_freelists.org> on
>> behalf of kunwar singh <krishsingh.111_at_gmail.com>
>> Sent: 05 August 2018 17:24:25
>> To: sachin pawar
>> Cc: oracle-l_at_freelists.org
>> 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_at_gmail.com<mailto:
>> getsach_at_gmail.com>> 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_at_gmail.com
>> <mailto: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','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
>

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