This discussion is archived
1 2 3 Previous Next 31 Replies Latest reply: Oct 3, 2011 11:16 AM by Hemant K Chitale RSS

10200 trace does not work

856121 Newbie
Currently Being Moderated
There is table T with 3 number columns (a,b,c) and index on column A.
Table is small and has a few rows.

I executed
alter session set optimizer_dynamic_sampling=0;
alter system flush buffer_cache;
alter session set events '10046 trace name context forever, level 8';
ALTER SESSION SET EVENTS '10200 trace name context forever, level 1';
insert into t values(2,null,null);
And tracefile contains:
*** ACTION NAME:() 2011-10-02 19:16:01.923
*** MODULE NAME:(SQL*Plus) 2011-10-02 19:16:01.923
*** SERVICE NAME:(SYS$USERS) 2011-10-02 19:16:01.923
*** SESSION ID:(1.60022) 2011-10-02 19:16:01.922
WAIT #5: nam='SQL*Net message to client' ela= 8 driver id=1413697536 #bytes=1 p3=0 obj#=826883 tim=9504546816500
WAIT #5: nam='SQL*Net message from client' ela= 63577 driver id=1413697536 #bytes=1 p3=0 obj#=826883 tim=9504546881660
=====================
PARSING IN CURSOR #6 len=68 dep=0 uid=2500 oct=42 lid=2500 tim=9504546882069 hv=2008936627 ad='0'
ALTER SESSION SET EVENTS '10200 trace name context forever, level 1'
END OF STMT
PARSE #6:c=0,e=228,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=9504546882065
EXEC #6:c=0,e=261,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=9504546882526
WAIT #6: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=826883 tim=9504546882562
WAIT #6: nam='SQL*Net message from client' ela= 63661 driver id=1413697536 #bytes=1 p3=0 obj#=826883 tim=9504546946264
=====================
PARSING IN CURSOR #4 len=33 dep=0 uid=2500 oct=2 lid=2500 tim=9504546948575 hv=3365441265 ad='ba6358c8'
insert into t values(2,null,null)
END OF STMT
PARSE #4:c=10000,e=2054,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=2,tim=9504546948570
WAIT #4: nam='db file sequential read' ela= 773 file#=224 block#=506129 blocks=1 obj#=1807603 tim=9504546949661
WAIT #4: nam='db file sequential read' ela= 334 file#=224 block#=506130 blocks=1 obj#=1807603 tim=9504546950075
WAIT #4: nam='db file sequential read' ela= 338 file#=88 block#=113105 blocks=1 obj#=0 tim=9504546950527
WAIT #4: nam='db file sequential read' ela= 8527 file#=88 block#=59778 blocks=1 obj#=0 tim=9504546959170
WAIT #4: nam='db file sequential read' ela= 515 file#=224 block#=506258 blocks=1 obj#=1807604 tim=9504546959940
EXEC #4:c=0,e=11346,p=5,cr=1,cu=5,mis=0,r=1,dep=0,og=2,tim=9504546960051
WAIT #4: nam='SQL*Net message to client' ela= 8 driver id=1413697536 #bytes=1 p3=0 obj#=1807604 tim=9504546960229
As we can see tracefile does not contain extra info about consistent gets (10200).

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?
  • 1. Re: 10200 trace does not work
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    Set event 10200 before setting event 10046 in the session.


    Hemant K Chitale
  • 2. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    the same result
  • 3. Re: 10200 trace does not work
    sb92075 Guru
    Currently Being Moderated
    853118 wrote:
    There is table T with 3 number columns (a,b,c) and index on column A.
    Table is small and has a few rows.

    I executed
    alter session set optimizer_dynamic_sampling=0;
    alter system flush buffer_cache;
    alter session set events '10046 trace name context forever, level 8';
    ALTER SESSION SET EVENTS '10200 trace name context forever, level 1';
    insert into t values(2,null,null);
    How to find what was read in cr mode?
    rhetorical question - Why should INSERT do any Read; CR or otherwise?
    would not multiple SELECT be a better test?
  • 4. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    sb92075 wrote:
    rhetorical question - Why should INSERT do any Read; CR or otherwise?
    It's a funny quesion. Did you read section "physical reads were" above?
  • 5. Re: 10200 trace does not work
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    See :
    Connected to:
    Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
    With the Partitioning, OLAP, Data Mining and Real Application Testing options
    
    SQL> create table T (col_1 number, col_2 varchar2(5), col_3 varchar(5));
    
    Table created.
    
    SQL> alter system flush buffer_cache;
    
    System altered.
    
    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,'ABC',NULL);
    
    1 row created.
    
    SQL> exit
    Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
    With the Partitioning, OLAP, Data Mining and Real Application Testing options
    [oracle@localhost ~]$ 
    [oracle@localhost app]$ cd
    [oracle@localhost ~]$ cd app/oracle/diag/rdbms/orcl/orcl/trace
    [oracle@localhost trace]$ 
    From the trace file, selected lines :
    PARSING IN CURSOR #2 len=35 dep=0 uid=184 oct=2 lid=184 tim=1317628978945209 hv=4035250269 ad='39208700' sqlid='7qbgapvs8a22x'
    insert into T values (1,'ABC',NULL)
    END OF STMT
    PARSE #2:c=100984,e=196676,p=5,cr=5,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1317628978945153
    =====================
    PARSING IN CURSOR #3 len=452 dep=1 uid=0 oct=3 lid=0 tim=1317628978957880 hv=4125516341 ad='3f962a60' sqlid='9gkq7rruycsjp'
    select parttype, partcnt, partkeycols, flags, defts#, defpctfree, defpctused, definitrans, defmaxtrans, deftiniexts, defextsize, defminexts, defmaxexts, defextpct, deflists, defgroups, deflogging, spare1, mod(spare2, 256) subparttype, mod(trunc(spare2/256), 256) subpartkeycols, mod(trunc(spare2/65536), 65536) defsubpartcnt, mod(trunc(spare2/4294967296), 256) defhscflags, mod(spare3, 256) interval_dty, rowid, defmaxsize from partobj$ where obj# = :1
    END OF STMT
    PARSE #3:c=4999,e=9536,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=1317628978957871
    =====================
    PARSING IN CURSOR #7 len=210 dep=2 uid=0 oct=3 lid=0 tim=1317628978965901 hv=864012087 ad='3f9510ac' sqlid='96g93hntrzjtr'
    select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
    END OF STMT
    PARSE #7:c=2000,e=2270,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=3,plh=0,tim=1317628978965768
    EXEC #7:c=8000,e=14593,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=3,plh=2239883476,tim=1317628978980994
    ktrgtc2(): started for block <0x0000 : 0x00400b49> objd: 0x000001aa
      env: (scn: 0x0000.004f5e7c  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.004f5e6f)
    showing 0x2d7f4b00 400b49 (1) dscn ffffffff:ffff bcrp ffff:ffffffff, bestcrp (nil)
    ktrexc(): returning 2 on:  0x106e193c  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
    new dscn ffff:ffffffff ret=2
    ktrgtc2(): completed for block <0x0000 : 0x00400b49> objd: 0x000001aa
    ktrget2(): started for block  <0x0000 : 0x0040768d> objd: 0x000001aa
    env: (scn: 0x0000.004f5e7c  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.004f5e6f)
    ktrgcm(): completed for block  <0x0000 : 0x0040768d> objd: 0x000001aa
    ktrget2(): completed for  block <0x0000 : 0x0040768d> objd: 0x000001aa
    ktrget2(): started for block  <0x0000 : 0x00400b3a> objd: 0x000001a8
    env: (scn: 0x0000.004f5e7c  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.004f5e6f)
    ktrgcm(): completed for block  <0x0000 : 0x00400b3a> objd: 0x000001a8
    ktrget2(): completed for  block <0x0000 : 0x00400b3a> objd: 0x000001a8
    FETCH #7:c=13998,e=63440,p=3,cr=3,cu=0,mis=0,r=1,dep=2,og=3,plh=2239883476,tim=1317628979046433
    STAT #7 id=1 cnt=1 pid=0 pos=1 obj=424 op='TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=3 pw=0 time=0 us)'
    STAT #7 id=2 cnt=1 pid=1 pos=1 obj=426 op='INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=2 pw=0 time=0 us)'
    CLOSE #7:c=0,e=213,dep=2,type=3,tim=1317628979046811
    =====================
    and so on...
    CURSOR#7 is at recursive depth=2.
    CURSOR#3 is at recursive depth=1.
    CURSor#2 is actually my SQL statement.

    Much further down
    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
    Hemant K Chitale
  • 6. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    Hemant, unfortunately your example is no good.
    Hemant K Chitale wrote:
    Much further down
    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
    So, your simple insert
    insert into T values (1,'ABC',NULL)
    has done 540 consistent reads and 74 current, spent 2.5 seconds (1.2s on CPU) - and it all during execute phase, not parsing.
    When STAT row shows that were no consistent gets (that is only current reads) during execution.
    Are you sure that you show us what were really happaned? Show full trace file please.

    The 10200 output in your case is from parsing, so please if you will do the same test in the future do it without parsing please (execute the same statement before test).
  • 7. Re: 10200 trace does not work
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    EXCUSE ME ????

    We began with your assertion : "As we can see tracefile does not contain extra info about consistent gets (10200)."

    I demonstrated how the trace file does show event 10200 activity.



    Hemant K Chitale

    PS : 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.

    Edited by: Hemant K Chitale on Oct 3, 2011 4:47 PM
  • 8. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    Sorry, Hemant, if I was not enough precise.

    My question is not about usual 10200. I wrote why I do it and what is my aim:
    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?
    Thus, my question is exactly consistent gets during execution of "insert values".

    Thus
    a) your example not answer the question about consistent gets during "insert values"
    b) your example is not correct - compare EXEC #2 and STAT#2. Maybe you did cut wrong.
  • 9. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    >
    PS : 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.

    Edited by: Hemant K Chitale on Oct 3, 2011 4:47 PM
    So, you insist that your "insert values" did 540 reads in consistent mode and 73 in current during execution phase?
    Could you please show us full trace file?

    I suggest that your EXEC #2 is from another cursor. It is after STAT #2 (when EXEC #2 should be finished) and is not compartible with STAT #2 by figures.
  • 10. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    All,
    is it normal to hear something like this
    Hemant K Chitale wrote:
    PS : 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.
    from Oracle ACE member?
    No problem, just something new about Oracle ACE for me.
  • 11. Re: 10200 trace does not work
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    853118 wrote:
    There is table T with 3 number columns (a,b,c) and index on column A.
    Table is small and has a few rows.

    I executed
    alter session set optimizer_dynamic_sampling=0;
    alter system flush buffer_cache;
    alter session set events '10046 trace name context forever, level 8';
    ALTER SESSION SET EVENTS '10200 trace name context forever, level 1';
    insert into t values(2,null,null);
    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
    Are you in the middle of a transaction
    As we can see tracefile does not contain extra info about consistent gets (10200).

    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?
    You can't trust any event to do exactly what the Internet gossip says, and you can't even assume that the trace file is 100% accurate.
    If you want to find out which blocks are read in CR mode then you could try querying x$bh for any buffers where the state is not free (state 0).

    Regards
    Jonathan Lewis
  • 12. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    Jonathan Lewis wrote:
    If you want to find out which blocks are read in CR mode then you could try querying x$bh for any buffers where the state is not free (state 0).
    Thanks, Jonathan.

    I have done:
    1. flush buffer cache
    2. insert .. values
    3. v$bh contains only (except free) some blocks with xcur status.

    Do you believe that all of them were read in cr mode?
  • 13. Re: 10200 trace does not work
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    853118 wrote:
    Jonathan Lewis wrote:
    If you want to find out which blocks are read in CR mode then you could try querying x$bh for any buffers where the state is not free (state 0).
    Thanks, Jonathan.

    I have done:
    1. flush buffer cache
    2. insert .. values
    3. v$bh contains only (except free) some blocks with xcur status.

    Do you believe that all of them were read in cr mode?
    No

    Regards
    Jonathan Lewis
  • 14. Re: 10200 trace does not work
    856121 Newbie
    Currently Being Moderated
    Jonathan Lewis wrote:

    No
    But exec call still contains cr=1.

    The table without index now.
1 2 3 Previous Next

Legend

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