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
  • 30. Re: 10200 trace does not work
    CharlesHooper Expert
    Currently Being Moderated
    853118 wrote:
    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.
    Here is something that is possibly interesting. An Oracle-L message:
    http://www.freelists.org/post/oracle-l/Logical-IO,12

    Referenced the following article:
    http://www.hellodba.com/reader.php?ID=39&lang=en

    That article suggested setting the tracepin_time parameter to 1 and then bouncing the database:
    alter system set "_trace_pin_time"=1 scope=spfile;
    After bouncing the database, connect session 1 as a normal user and session 2 as SYS.

    In session 1 (using the tablespace I created earlier):
    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;
    In session 2 (wait a couple of seconds before entering the SELECT statement:
    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       2016      1
       0      1          1       2017      1
    In session 1:
    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);
    Back in session 2 (note that I have added * and a number to a couple of the rows:
    /
    
     TS#  FILE#    DBARFIL     DBABLK  STATE
    ---- ------ ---------- ---------- ------
       0      1          1       2016      1
       0      1          1       2017      1
       2      3          3        192      1  *  3
       2      3          3      16029      1  *  1
       5      5          5        128      1  *  
       5      5          5        427      1  *  2
       5      5          5        428      1  *  2
    Let's take a look at the trace file, note the "pin" and "pin release" lines that are a result of setting the tracepin_time parameter to a value of 1 (I have added numbers to some of the lines that correspond to the above output):
    PARSING IN CURSOR #367514528 len=34 dep=0 uid=62 oct=2 lid=62 tim=21584856863 hv=544833741 ad='7ffb77d8140' sqlid='96mny1hh7m06d'
    INSERT INTO T4 VALUES(2,NULL,NULL)
    END OF STMT
    PARSE #367514528:c=0,e=489,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=21584856863
    WAIT #367514528: nam='db file sequential read' ela= 156 file#=5 block#=128 blocks=1 obj#=71114 tim=21584857108
    pin ktswh28: ktsgsp dba 0x1400080:4 time 110020667
    WAIT #367514528: nam='db file scattered read' ela= 935 file#=5 block#=427 blocks=32 obj#=71114 tim=21584858155  2 ****
    pin ktswh72: ktsbget dba 0x14001ab:1 time 110021704                                                             2 
    WAIT #367514528: nam='db file sequential read' ela= 132 file#=3 block#=192 blocks=1 obj#=0 tim=21584858344      3 ****
    pin ktuwh59: ktugus:ktubnd dba 0xc000c0:25 time 110021892                                                       3 
    WAIT #367514528: nam='db file sequential read' ela= 130 file#=3 block#=16029 blocks=1 obj#=0 tim=21584858538    1 ****
    pin ktuwh09: ktugfb dba 0xc03e9d:26 time 110022085                                                              1 
    pin release        18 ktuwh09: ktugfb dba 0xc03e9d:26                                                           1
    pin release       428 ktswh72: ktsbget dba 0x14001ab:1                                                          2
    pin release       246 ktuwh59: ktugus:ktubnd dba 0xc000c0:25                                                    3
    EXEC #367514528:c=0,e=1731,p=35,cr=1,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=21584858629
    STAT #367514528 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=35 pw=0 time=1703 us)'
    WAIT #367514528: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=21584858681
    I do not claim to fully understand what appears above (http://www.jlcomp.demon.co.uk/buffer_usage.html might provide some helpful infomation). However, you may notice that block 128 in file 5 does not have a corresponding "pin release".
    SELECT
      HEADER_FILE,
      HEADER_BLOCK
    FROM
      DBA_SEGMENTS
    WHERE
      SEGMENT_NAME='T4';
    
    HEADER_FILE HEADER_BLOCK
    ----------- ------------
              5          128
    Block 128 in file 5 is the segment header block for the T4 test table. I suspect that it is the segment header block that is accounting for the 1 consistent read in the EXEC and STAT lines. My best guess is that Oracle is re-reading that block while it is still pinned, and is thus considering that read as a consistent get, even though the session already has the block pinned. That re-read after being pinned could also explain why a 10200 trace would not show that read. Opinions?

    Charles Hooper
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 31. Re: 10200 trace does not work
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    why was 1 consistent get.
    A current get for a block is executed as a consistent get the first time.

    Event 10200 does not show such consistent gets.
    Please, be honest.
    I hope that you will be able to go far in your career inspite of casting aspersions on the honesty of others. Goodbye !

    Hemant K Chitale
1 2 3 Previous Next

Legend

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