1 2 3 Previous Next 31 Replies Latest reply: Oct 3, 2011 1:16 PM by Hemant K Chitale Go to original post RSS
      • 15. Re: 10200 trace does not work
        856121
        Jonathan Lewis wrote:
        Which version of Oracle
        Are the tablespaces using freelist managment or ASSM
        Is the index unique or non-unique
        What did you do to the table in the moments before this code -
        Is there pre-existing data
        Is it freshly created
        11.1.0.6, 11.2.0.2
        freelists
        there are no indexes now
        the table just created, may has one row for example, not middle of transaction

        in fact code is simple
        create table t (a number, b number);
        <10046>
        insert into t values(0,0);
        • 16. Re: 10200 trace does not work
          Charles Hooper
          853118 wrote:
          11.1.0.6, 11.2.0.2
          freelists
          there are no indexes now
          the table just created, may has one row for example, not middle of transaction

          in fact code is simple
          create table t (a number, b number);
          <10046>
          insert into t values(0,0);
          You will probably want to supply a full test case. Make certain that your test case is not executed by SYS.

          First, a sample CREATE TABLESPACE (created by SYS):
          CREATE SMALLFILE TABLESPACE "LOCAL_UNIFORM1M" DATAFILE 'C:\Oracle\OraData\OR1122D\locun1MOR1122.dbf' SIZE 100M AUTOEXTEND ON NEXT 10M
              MAXSIZE UNLIMITED LOGGING EXTENT MANAGEMENT LOCAL UNIFORM SIZE 1M SEGMENT SPACE MANAGEMENT MANUAL;
          The setup in the non-SYS user session:
          DROP TABLE T4 PURGE;
           
          CREATE TABLE T4(
            C1 NUMBER,
            C2 VARCHAR2(10),
            C3 VARCHAR2(10))
            TABLESPACE LOCAL_UNIFORM1M;
           
          INSERT INTO
            T4
          SELECT
            ROWNUM+10,
            TO_CHAR(ROWNUM),
            TO_CHAR(ROWNUM+10)
          FROM
            DUAL
          CONNECT BY
            LEVEL<=100000;
           
          COMMIT;
           
          EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T4',CASCADE=>TRUE)
           
          INSERT INTO T4 VALUES(1,NULL,NULL);
          COMMIT;
          Back in the SYS session:
          ALTER SYSTEM FLUSH BUFFER_CACHE;
          ALTER SYSTEM FLUSH BUFFER_CACHE;
           
          SELECT
            TS#,
            FILE#,
            DBARFIL,
            DBABLK,
            STATE
          FROM
            X$BH
          WHERE
            STATE<>0
          ORDER BY
            TS#,
            FILE#,
            DBABLK;
           
           TS#  FILE#    DBARFIL     DBABLK  STATE
          ---- ------ ---------- ---------- ------
             0      1          1        233      1
             0      1          1        401      1
             0      1          1       2016      1
             0      1          1       2017      1
             0      1          1      73586      1
             2      3          3          2      1
             2      3          3        144      1
             2      3          3       4834      1
          Now, quickly jump back to the non-SYS session:
          ALTER SESSION SET TRACEFILE_IDENTIFIER = 'T4_NO_INDEX2';
          ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
          ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
           
          INSERT INTO T4 VALUES(2,NULL,NULL);
          And then back to the SYS session:
          SQL> /
           
           TS#  FILE#    DBARFIL     DBABLK  STATE
          ---- ------ ---------- ---------- ------
             0      1          1        233      1
             0      1          1        401      1
             0      1          1       2016      1
             0      1          1       2017      1
             0      1          1      73586      1
             2      3          3          2      1
             2      3          3        144      1
             2      3          3        224      1   *
             2      3          3       2116      1   *
             2      3          3       4834      1
             5      5          5        128      1   *
             5      5          5        427      1   *
          In the above, note that I have marked a couple of the lines with * - those lines were not found in the initial select.

          Let's take a look at the generated trace file (11.2.0.2):
          PARSING IN CURSOR #375342512 len=34 dep=0 uid=62 oct=2 lid=62 tim=14438649725 hv=544833741 ad='7ffb76d8120' sqlid='96mny1hh7m06d'
          INSERT INTO T4 VALUES(2,NULL,NULL)
          END OF STMT
          PARSE #375342512:c=0,e=613,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=14438649724
          WAIT #375342512: nam='db file sequential read' ela= 210 file#=5 block#=128 blocks=1 obj#=71112 tim=14438650023
          WAIT #375342512: nam='db file sequential read' ela= 238 file#=5 block#=427 blocks=1 obj#=71112 tim=14438650333
          WAIT #375342512: nam='db file sequential read' ela= 181 file#=3 block#=224 blocks=1 obj#=0 tim=14438650594
          WAIT #375342512: nam='db file sequential read' ela= 199 file#=3 block#=2116 blocks=1 obj#=0 tim=14438650829
          EXEC #375342512:c=0,e=1145,p=4,cr=1,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=14438650903
          STAT #375342512 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=4 pw=0 time=1115 us)'
          WAIT #375342512: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=14438650962
          Note in the above that there were 4 single block reads. The file# and block# found in the trace file match the query of X$BH that was suggested by Jonathan. It appears that the EXEC and STAT lines are only reporting 1 of the 4 consistent gets current reads. An ASSM AUTO tablespace with or without an index on the table will also result in cr=1 in the EXEC and STAT lines.

          Charles Hooper
          http://hoopercharles.wordpress.com/
          IT Manager/Oracle DBA
          K&M Machine-Fabricating, Inc.

          Edited by: Charles Hooper on Oct 3, 2011 10:23 AM
          Correction:
          STATE=1 in X$BH is xcur in V$BH (current version of the block)
          STAT=3 in X$BH is cr in V$BH (consistent read version).

          Thus, it appears that there were no consistent read versions, but there were 4 current read versions - 1 of those might be counted as a consistent read version for the STAT and EXEC lines in the trace file.
          • 17. Re: 10200 trace does not work
            856121
            Hi Charles,
            Thus, it appears that there were no consistent read versions, but there were 4 current read versions - 1 of those might be counted as a
            consistent read version for the STAT and EXEC lines in the trace file.
            So, Oracle lies us that where 1 cr + 3 cu where were 4 cu?
            Sounds dubious.

            And in my tests:
            n cu, n physical reads, and 1 cr.
            • 18. Re: 10200 trace does not work
              Hemant K Chitale
              Unfortunately, I cannot upload the trace file from behind this network and it's too large to copy-paste section by section.

              However, here's a tkprof for that statement :
              SQL ID: 7qbgapvs8a22x
              Plan Hash: 0
              insert into T
              values
               (1,'ABC',NULL)
              
              
              call     count       cpu    elapsed       disk      query    current        rows
              ------- ------  -------- ---------- ---------- ---------- ----------  ----------
              Parse        1      0.10       0.19          5          5          0           0
              Execute      1      0.00       2.57          0        540         45           1
              Fetch        0      0.00       0.00          0          0          0           0
              ------- ------  -------- ---------- ---------- ---------- ----------  ----------
              total        2      0.10       2.77          5        545         45           1
              
              Misses in library cache during parse: 1
              Misses in library cache during execute: 1
              Optimizer mode: ALL_ROWS
              Parsing user id: 184
              
              Rows     Row Source Operation
              -------  ---------------------------------------------------
                    0  LOAD TABLE CONVENTIONAL  (cr=0 pr=0 pw=0 time=0 us)
              
              ********************************************************************************
              Look back at my earlier posting and try to understand why I showed that there were recursive statements with different DEPTH levels.
              This single INSERT statement may call a number of recursive SQLs and the sum of activity by the recursive SQLs is accounted as 540 consistent-gets and 45 current gets.

              So, if I execute an INSERT now after restarting the server :
              SQL> set autotrace on
              SQL> insert into T values (2,'DEF',NULL);
              
              1 row created.
              
              
              Execution Plan
              ----------------------------------------------------------
              
              ---------------------------------------------------------------------------------
              | Id  | Operation                | Name | Rows  | Bytes | Cost (%CPU)| Time     |
              ---------------------------------------------------------------------------------
              |   0 | INSERT STATEMENT         |      |     1 |   100 |     1   (0)| 00:00:01 |
              |   1 |  LOAD TABLE CONVENTIONAL | T    |       |       |            |          |
              ---------------------------------------------------------------------------------
              
              
              Statistics
              ----------------------------------------------------------
                      214  recursive calls
                        5  db block gets
                       32  consistent gets
                       11  physical reads
                        0  redo size
                      673  bytes sent via SQL*Net to client
                      607  bytes received via SQL*Net from client
                        3  SQL*Net roundtrips to/from client
                        6  sorts (memory)
                        0  sorts (disk)
                        1  rows processed
              
              SQL> 
              I have 214 recursive calls for that one INSERT. In this instance, there are 32 consistent gets and 5 current gets.

              In the same session (no restart now), if I run another insert :
              SQL> insert into T values (3,'XYZ',null);
              
              1 row created.
              
              
              Execution Plan
              ----------------------------------------------------------
              
              ---------------------------------------------------------------------------------
              | Id  | Operation                | Name | Rows  | Bytes | Cost (%CPU)| Time     |
              ---------------------------------------------------------------------------------
              |   0 | INSERT STATEMENT         |      |     1 |   100 |     1   (0)| 00:00:01 |
              |   1 |  LOAD TABLE CONVENTIONAL | T    |       |       |            |          |
              ---------------------------------------------------------------------------------
              
              
              Statistics
              ----------------------------------------------------------
                        1  recursive calls
                        3  db block gets
                        1  consistent gets
                        0  physical reads
                      296  redo size
                      673  bytes sent via SQL*Net to client
                      607  bytes received via SQL*Net from client
                        3  SQL*Net roundtrips to/from client
                        1  sorts (memory)
                        0  sorts (disk)
                        1  rows processed
              
              SQL> 
              Now, since Oracle does not have to do much recursive activity to get the definition of the target table T and any statistics, there is only 1 recursive call and 1 consistent get, but still 3 current gets.

              Here's a hint : Why does the AUTOTRACE show 1 row and 100bytes ? If you know why, you should know about the recursive calls as well.

              The point is :
              Your test can return different results depending on what actions Oracle has to perform "behind the scenes". You know that the presence of indexes is one of the dependencies. You have NOT accounted for recursive calls being a factor.
              Similarly, I was suprised that you could not distinguish between consistent gets and current gets and yet was going so far as to attempt a 10200 trace. I suggest that you restart your Oracle learning.
              I stand by my statement :

              And, by the way, if you do NOT understand these two elements :
              cr=540,cu=73

              don't even bother trying to generate a 10200 trace.
              Go back to your University.


              Hemant K Chitale
              • 19. Re: 10200 trace does not work
                Hemant K Chitale
                Your first question was :
                As we can see tracefile does not contain extra info about consistent gets (10200).
                Did you or did you NOT get an answer to your question ?

                Hemant K Chitale
                • 20. Re: 10200 trace does not work
                  856121
                  Hemant K Chitale wrote:
                  So, if I execute an INSERT now after restarting the server :
                  SQL> set autotrace on
                  SQL> insert into T values (2,'DEF',NULL);
                  
                  1 row created.
                  
                  
                  Execution Plan
                  ----------------------------------------------------------
                  
                  ---------------------------------------------------------------------------------
                  | Id  | Operation                | Name | Rows  | Bytes | Cost (%CPU)| Time     |
                  ---------------------------------------------------------------------------------
                  |   0 | INSERT STATEMENT         |      |     1 |   100 |     1   (0)| 00:00:01 |
                  |   1 |  LOAD TABLE CONVENTIONAL | T    |       |       |            |          |
                  ---------------------------------------------------------------------------------
                  
                  
                  Statistics
                  ----------------------------------------------------------
                  214  recursive calls
                  5  db block gets
                  32  consistent gets
                  11  physical reads
                  0  redo size
                  673  bytes sent via SQL*Net to client
                  607  bytes received via SQL*Net from client
                  3  SQL*Net roundtrips to/from client
                  6  sorts (memory)
                  0  sorts (disk)
                  1  rows processed
                  
                  SQL> 
                  I have 214 recursive calls for that one INSERT. In this instance, there are 32 consistent gets and 5 current gets.
                  The most of them from parsing. I asked you to avoid (hard) parsing in your test.
                  btw,
                  call     count       cpu    elapsed       disk      query    current        rows
                  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                  Parse        1      0.10       0.19          5          5          0           0
                  Execute      1      0.00       2.57          0        540         45           1
                  Fetch        0      0.00       0.00          0          0          0           0
                  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                  total        2      0.10       2.77          5        545         45           1
                  
                  Misses in library cache during parse: 1
                  Misses in library cache during execute: 1
                  Misses in library cache during execute: 1
                  I suggest, it also might be a parsing. I do not need to see consistent reads from parsing.

                  The point is :
                  Your test can return different results depending on what actions Oracle has to perform "behind the scenes". You know that the presence of indexes is one of the dependencies. You have NOT accounted for recursive calls being a factor.
                  Maybe you think that I asked you about "different results" or recursive calls?
                  I need to repeat the question: I am finding which block(s) was read in cr mode during execution of "insert..values" statement. Without parsing and additional recursive calls.
                  Similarly, I was suprised that you could not distinguish between consistent gets and current gets and yet was going so far as to attempt a 10200 trace.
                  It is your fantasy.


                  Hemant,
                  you did not understand the question,
                  showed example which nothing speaks about the question (only that 10200 trace works, thanks I knew it, and why I should execute it before 10046 !? ;) ) with (stupid) mistakes,
                  and after that you began to disgrace Oracle ACE.

                  p.s.
                  And what is it?
                  (look at the "execute")
                  call     count       cpu    elapsed       disk      query    current        rows
                  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                  Parse        1      0.10       0.19          5          5          0           0
                  Execute      1      0.00       2.57          0        540         45           1
                  Fetch        0      0.00       0.00          0          0          0           0
                  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                  total        2      0.10       2.77          5        545         45           1
                  45 current reads and 0.00 cpu time?
                  But you showed us 73 current reads and 1.29 of cpu time?!
                  STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=0 pr=0 pw=0 time=0 us)'
                  EXEC #2:c=1290804,e=2575462,p=76,cr=540,cu=73,mis=1,r=1,dep=0,og=1,plh=0,tim=1317628981521123
                  I suggest it is your fantasy again. I think you are afraid to admit it and paint numbers.
                  • 21. Re: 10200 trace does not work
                    856121
                    Hemant K Chitale wrote:
                    Your first question was :
                    As we can see tracefile does not contain extra info about consistent gets (10200).
                    Did you or did you NOT get an answer to your question ?
                    Hemant, it was not a question. Do you see a question mark? No, you do not. Because this is not a question.
                    Look at the last sentence in my first post:
                    My aim to find out which blocks are read in cr mode.
                    In this exact case 1 block, in other the same inserts sometimes I see more than one block, for example 3.
                    
                    physical reads were:
                    1. table header
                    2. table block
                    3. undo header
                    4. undo block
                    5. index leaf block
                    
                    How to find what was read in cr mode?
                    • 22. Re: 10200 trace does not work
                      Hemant K Chitale
                      I am finding which block(s) was read in cr mode during execution of "insert..values" statement. Without parsing and additional recursive calls.
                      AN "INSERT ... VALUES .. " will be parsed if the SQL statement is not exactly the same. That is why I demonstrated in the subsequent post 1 recursive call, 3 current gets and 1 consistent get.
                      45 current reads and 0.00 cpu time?
                      But you showed us 73 current reads and 1.29 of cpu time?!
                      Because the tkprof does not present exactly the same information as the raw trace.
                      Here are the pieces again :
                      STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=0 pr=0 pw=0 time=0 us)'
                      EXEC #2:c=1290804,e=2575462,p=76,cr=540,cu=73,mis=1,r=1,dep=0,og=1,plh=0,tim=1317628981521123
                      
                      
                      
                      SQL ID: 7qbgapvs8a22x
                      Plan Hash: 0
                      insert into T
                      values
                       (1,'ABC',NULL)
                      
                      
                      call     count       cpu    elapsed       disk      query    current        rows
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      Parse        1      0.10       0.19          5          5          0           0
                      Execute      1      0.00       2.57          0        540         45           1
                      Fetch        0      0.00       0.00          0          0          0           0
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      total        2      0.10       2.77          5        545         45           1
                      
                      Misses in library cache during parse: 1
                      Misses in library cache during execute: 1
                      Optimizer mode: ALL_ROWS
                      Parsing user id: 184
                      
                      Rows     Row Source Operation
                      -------  ---------------------------------------------------
                            0  LOAD TABLE CONVENTIONAL  (cr=0 pr=0 pw=0 time=0 us)
                      
                      ********************************************************************************
                      
                      
                      OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
                      
                      call     count       cpu    elapsed       disk      query    current        rows
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      Parse        1      0.10       0.19          5          5          0           0
                      Execute      1      0.00       2.57          0        540         45           1
                      Fetch        0      0.00       0.00          0          0          0           0
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      total        2      0.10       2.77          5        545         45           1
                      
                      Misses in library cache during parse: 1
                      Misses in library cache during execute: 1
                      
                      
                      OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
                      
                      call     count       cpu    elapsed       disk      query    current        rows
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      Parse       26      0.15       0.23          0          0          0           0
                      Execute    163      0.63       1.32         12         16         31           5
                      Fetch      204      0.54       1.15         66        526          0         959
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      total      393      1.33       2.71         78        542         31         964
                      
                      Misses in library cache during parse: 26
                      Misses in library cache during execute: 26
                      
                          1  user  SQL statements in session.
                        163  internal SQL statements in session.
                        164  SQL statements in session.
                      Yes, obviously there's a difference.
                      It's not my fantasy. And I don't paint the numbers.
                      (I did show that I was using 11.2.0.1)


                      Both Jonathan and Carl have pointed out that events and trace do not always report accurately 100%

                      Depending on the "background" information in your test (does Oracle have to execute at least 1 recursive call ? Does it have to read the segment header ? Does it have to create the segment itself at the first insert ? Does it have allocate an additional extent for the row ?), the "results" that you see can vary.

                      Hemant K Chitale
                      • 23. Re: 10200 trace does not work
                        Hemant K Chitale
                        Hemant, it was not a question. Do you see a question mark? No, you do not. Because this is not a question.
                        The title of your post is "10200 trace does not work"
                        The trace you present does not show evidence of 10200
                        You then add the line "As we can see tracefile does not contain extra info about consistent gets (10200)."
                        So, it seemed to me that it was logical to to interpret your post as "I enabled event 10200 trace but I see no information about consistent gets in the trace file".
                        Therefore, I presented a case to show how you could see 10200's presentation of evidence of consistent gets.
                        The 10200 evidence also identifies the file and block and objd and these can be used to identify which blocks of which segments (in the case of recursive calls against the data dictionary, SYS objects) were read.
                        If you avoided parsing, you'd avoid the evidence of these consistent gets and you would not see the 10200 evidence.


                        Hemant K Chitale
                        • 24. Re: 10200 trace does not work
                          856121
                          Hemant K Chitale wrote:
                          Because the tkprof does not present exactly the same information as the raw trace.
                          Here are the pieces again :
                          STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=0 pr=0 pw=0 time=0 us)'
                          EXEC #2:c=1290804,e=2575462,p=76,cr=540,cu=73,mis=1,r=1,dep=0,og=1,plh=0,tim=1317628981521123
                          
                          
                          
                          SQL ID: 7qbgapvs8a22x
                          Plan Hash: 0
                          insert into T
                          values
                          (1,'ABC',NULL)
                          
                          
                          call     count       cpu    elapsed       disk      query    current        rows
                          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                          Parse        1      0.10       0.19          5          5          0           0
                          Execute      1      0.00       2.57          0        540         45           1
                          Fetch        0      0.00       0.00          0          0          0           0
                          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                          total        2      0.10       2.77          5        545         45           1
                          ...
                          Yes, obviously there's a difference.
                          It's not my fantasy. And I don't paint the numbers.
                          (I did show that I was using 11.2.0.1)
                          Hemant, sorry, but what do you mean? Figures in tkprof summary of statement is exactly from calls (like EXEC).

                          Could you provide excerpt from raw trace where EXEC call with dep=0 will contain cpu time 1.29s and current=73, but tkprof output of this statement will contain 0.00 cpu time and 45 current? It is not hard to you. Just excerpt from your raw trace.
                          I think that you will not be able do it. Because these figures is your fantasy.

                          Depending on the "background" information in your test (does Oracle have to execute at least 1 recursive call ? Does it have to read the segment header ? Does it have to create the segment itself at the first insert ? Does it have allocate an additional extent for the row ?), the "results" that you see can vary.
                          Obviously there were no new extent allocation. 3 current reads + 1 consistent get.
                          • 25. Re: 10200 trace does not work
                            Hemant K Chitale
                            If I run this :
                            SQL> drop table T purge;
                            
                            Table dropped.
                            
                            SQL> create table T (col_1 number, col_2 varchar2(50), col_3 varchar2(50)) pctfree 99;
                            
                            Table created.
                            
                            SQL> insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'));
                            
                            1 row created.
                            
                            SQL> insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'));
                            
                            1 row created.
                            
                            SQL> alter session set events '10200 trace name context forever, level 1';
                            
                            Session altered.
                            
                            SQL> alter session set events '10046 trace name context forever, level 1';
                            
                            Session altered.
                            
                            SQL> insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'));
                            
                            1 row created.
                            
                            SQL> insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'));
                            
                            1 row created.
                            
                            SQL> insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'));
                            
                            1 row created.
                            
                            SQL> exit
                            I see :
                            PARSING IN CURSOR #12 len=58 dep=0 uid=184 oct=2 lid=184 tim=1317665951604803 hv=2107442515 ad='3a49ed38' sqlid='7v5a30xytu1am'
                            insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'))
                            END OF STMT
                            PARSE #12:c=16997,e=56720,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1317665951604649
                            EXEC #12:c=5000,e=5857,p=0,cr=1,cu=4,mis=0,r=1,dep=0,og=1,plh=0,tim=1317665951611297
                            STAT #12 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=0 us)'
                            
                            *** 2011-10-04 02:19:13.812
                            CLOSE #12:c=999,e=1627,dep=0,type=0,tim=1317665953811790
                            ===================== 
                            PARSING IN CURSOR #10 len=58 dep=0 uid=184 oct=2 lid=184 tim=1317665953818146 hv=2107442515 ad='3a49ed38' sqlid='7v5a30xytu1am'
                            insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'))
                            END OF STMT
                            PARSE #10:c=1000,e=1081,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1317665953818089
                            EXEC #10:c=2000,e=2441,p=0,cr=1,cu=4,mis=0,r=1,dep=0,og=1,plh=0,tim=1317665953821740
                            STAT #10 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=0 us)'
                            
                            *** 2011-10-04 02:19:16.080
                            CLOSE #10:c=1000,e=688,dep=0,type=0,tim=1317665956080406
                            PARSING IN CURSOR #5 len=58 dep=0 uid=184 oct=2 lid=184 tim=1317665956082648 hv=2107442515 ad='3a49ed38' sqlid='7v5a30xytu1am'
                            insert into T values (1,rpad('A',45,'X'),rpad('B',45,'X'))
                            END OF STMT
                            PARSE #5:c=0,e=736,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1317665956082527
                            EXEC #5:c=4000,e=26281,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,plh=0,tim=1317665956109590
                            STAT #5 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=0 us)'
                            
                            *** 2011-10-04 02:19:19.310
                            XCTEND rlbk=0, rd_only=0, tim=1317665959310001
                            and
                            SQL ID: 7v5a30xytu1am
                            Plan Hash: 0
                            insert into T
                            values
                             (1,rpad('A',45,'X'),rpad('B',45,'X'))
                            
                            
                            call     count       cpu    elapsed       disk      query    current        rows
                            ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                            Parse        3      0.01       0.05          0          0          0           0
                            Execute      3      0.01       0.03          0          3         13           3
                            Fetch        0      0.00       0.00          0          0          0           0
                            ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                            total        6      0.02       0.09          0          3         13           3
                            
                            Misses in library cache during parse: 1
                            Optimizer mode: ALL_ROWS
                            Parsing user id: 184
                            
                            Rows     Row Source Operation
                            -------  ---------------------------------------------------
                                  0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=0 us)
                            Note how the first INSERT call after enabling tracing still shows a "mis". There's still a parse there inspite of the two parses before enabling tracing.

                            Why were there 4 or 5 current gets for each EXEC ? With a PCTFREE of 99, I ensured that each row goes into a new block.
                            SQL> select dbms_rowid.ROWID_BLOCK_NUMBER(rowid) from t;
                            
                            DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
                            ------------------------------------
                                                           38259
                                                           38260
                                                           38261
                                                           38262
                                                           38263
                            
                            SQL> 
                            SQL> exec dbms_stats.gather_table_stats('','T',estimate_percent=>100);
                            
                            PL/SQL procedure successfully completed.
                            
                            SQL> select num_rows, avg_row_len, blocks from user_tables
                              2  where table_name = 'T';
                            
                              NUM_ROWS AVG_ROW_LEN     BLOCKS
                            ---------- ----------- ----------
                                     5          95          5
                            
                            SQL> 
                            In your test cases, you must confirm that the insert of the row does not have to go into a new block, does not have to allocate a new extent, does not have to update the segment header.

                            Hemant K Chitale

                            PS : This trace file does not show any evidence of additional information about consistent gets that event 10200 should show. So a review of such a trace file would conclude that "event 10200 does not work".

                            Edited by: Hemant K Chitale on Oct 4, 2011 12:49 AM
                            Corrected the test case. The test case wasn't really inserting each row into a seperate block because the Row Length was inadequate. In this test case, each row does go into a separate block.

                            Edited by: Hemant K Chitale on Oct 4, 2011 2:17 AM
                            • 26. Re: 10200 trace does not work
                              856121
                              Hemant K Chitale wrote:
                              If you avoided parsing, you'd avoid the evidence of these consistent gets and you would not see the 10200 evidence.
                              And again nonsense.
                              My the first example contains EXEC call without parsing and with cr=1.
                              And my questions are:
                              1. which block was read in cr mode in this exact case
                              2. why 10200 did not show this exact cr get?

                              An example from Charlse also does not contain parsing and contain cr gets.
                              • 27. Re: 10200 trace does not work
                                Hemant K Chitale
                                I think that you will not be able do it. Because these figures is your fantasy.
                                I am known to be honest.


                                Hemant K Chitale
                                • 28. Re: 10200 trace does not work
                                  856121
                                  Hemant K Chitale wrote:
                                  If I run this :
                                  I see :
                                  Your latest excerpt also contains cr=1 for inserts and does not contain 10200 output. It's about this topic.

                                  Why were there 3 current gets for each EXEC ? With ...
                                  In your test cases, you must confirm that ...
                                  I am not interested in why were 3 current reads, but why was 1 consistent get.
                                  And why 10200 output about this "get" does not present.
                                  • 29. Re: 10200 trace does not work
                                    856121
                                    Hemant K Chitale wrote:
                                    I think that you will not be able do it. Because these figures is your fantasy.
                                    I am known to be honest.
                                    Where is 1290804 of cpu time time and 73 current gets in your previous tkprof? ;-)

                                    This call
                                    STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=0 pr=0 pw=0 time=0 us)'
                                    EXEC #2:c=1290804,e=2575462,p=76,cr=540,cu=73,mis=1,r=1,dep=0,og=1,plh=0,tim=1317628981521123
                                    will not be shown as
                                    call     count       cpu    elapsed       disk      query    current        rows
                                    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                                    Parse        1      0.10       0.19          5          5          0           0
                                    Execute      1      0.00       2.57          0        540         45           1
                                    Fetch        0      0.00       0.00          0          0          0           0
                                    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                                    total        2      0.10       2.77          5        545         45           1
                                    I still be sure that you showed us what not happened in reality.
                                    Also, as I wrote, your EXEC call was after STAT row.

                                    Please, be honest.