This discussion is archived
1 2 3 Previous Next 31 Replies Latest reply: Oct 3, 2011 11:16 AM by Hemant K Chitale Go to original post RSS
  • 15. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    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
    CharlesHooper Expert
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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 Oracle ACE
    Currently Being Moderated
    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 Oracle ACE
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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 Oracle ACE
    Currently Being Moderated
    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 Oracle ACE
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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 Oracle ACE
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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 Oracle ACE
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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 Newbie
    Currently Being Moderated
    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.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points