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

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