1 2 3 Previous Next 31 Replies Latest reply: Oct 3, 2011 1:16 PM by Hemant K Chitale RSS

    10200 trace does not work

    856121
      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
          Set event 10200 before setting event 10046 in the session.


          Hemant K Chitale
          • 2. Re: 10200 trace does not work
            856121
            the same result
            • 3. Re: 10200 trace does not work
              sb92075
              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
                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
                  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
                    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
                      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
                        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
                          >
                          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
                            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
                              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
                                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
                                  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
                                    Jonathan Lewis wrote:

                                    No
                                    But exec call still contains cr=1.

                                    The table without index now.
                                    1 2 3 Previous Next