Results 1 to 8 of 8
  1. #1
    Join Date
    Feb 2004
    Location
    Wiessrussland
    Posts
    10

    Unanswered: Translate trace result, time format???

    Hi, all

    can anybody tell what is <time=31 us> means, is that is some kind of units? or just geographical US???
    I did this trace with ALTER SESSION SET SQL_TRACE = TRUE/False, then tkprof..

    My output looks like below, actually I also want to confirm that my query also work correctly with partition rather then making Select from all table. I think that's the case, I see Partition mentioned here:

    I really appreciate you help and any good poitners where I can learn more about trace translation, I've tried to google and looks like everybody id dba, I could not find even what is time units are in trace..

    I also in my trace have elapsed=0, which probably means that it's really fast and rounded to 0?>> I just want to clock base line for my Procedure so I'll see how I can modify it. My SP do complicated select into GTT and one more with JOIN with GTT.

    Best
    Dai
    --------

    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 3 0.00 0.00 0 0 0 0
    Execute 3 0.00 0.00 0 15 2 36
    Fetch 1 0.00 0.00 0 3 0 1
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 7 0.00 0.00 0 18 2 37

    Rows Row Source Operation
    ------- ---------------------------------------------------
    0 VIEW (cr=0 pr=0 pw=0 time=48 us)
    0 COUNT (cr=0 pr=0 pw=0 time=44 us)
    0 FILTER (cr=0 pr=0 pw=0 time=41 us)
    0 VIEW (cr=0 pr=0 pw=0 time=37 us)
    0 SORT ORDER BY (cr=0 pr=0 pw=0 time=31 us)
    0 UNION-ALL (cr=0 pr=0 pw=0 time=15 us)
    0 NESTED LOOPS (cr=0 pr=0 pw=0 time=8 us)
    0 TABLE ACCESS FULL GTT_INTERM (cr=0 pr=0 pw=0 time=4 us)
    0 TABLE ACCESS BY GLOBAL INDEX ROWID TT_MAX_COLLECT PARTITION: ROW LOCATION ROW LOCATION (cr=0 pr=0 pw=0 time=0 us)
    0 INDEX UNIQUE SCAN CI_DEAL_PK1 (cr=0 pr=0 pw=0 time=0 us)(object id 68559)
    0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us)
    0 TABLE ACCESS FULL GTT_INTERM (cr=0 pr=0 pw=0 time=0 us)
    0 TABLE ACCESS BY GLOBAL INDEX ROWID TT_MAX_COLLECT PARTITION: ROW LOCATION ROW LOCATION (cr=0 pr=0 pw=0 time=0 us)
    0 INDEX UNIQUE SCAN CI_DEAL_PK1 (cr=0 pr=0 pw=0 time=0 us)(object id 68559)

    ************************************************** ******************************
    Last edited by DAINOVA; 10-19-10 at 19:32.

  2. #2
    Join Date
    Aug 2003
    Location
    Where the Surf Meets the Turf @Del Mar, CA
    Posts
    7,776
    Provided Answers: 1
    below may be an easier to observer & report statistics
    Code:
     sqlplus
    
    SQL*Plus: Release 11.2.0.1.0 Production on Tue Oct 19 15:37:36 2010
    
    Copyright (c) 1982, 2009, Oracle.  All rights reserved.
    
    Enter user-name: dbadmin/admindb
    
    Connected to:
    Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
    With the Partitioning, OLAP, Data Mining and Real Application Testing options
    
    SQL> set autotrace trace explain statistics
    SQL> select count(*) from user_tables;
    
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 4254542879
    
    --------------------------------------------------------------------------------
    --------
    
    | Id  | Operation		    | Name     | Rows  | Bytes | Cost (%CPU)| Ti
    me     |
    
    --------------------------------------------------------------------------------
    --------
    
    |   0 | SELECT STATEMENT	    |	       |     1 |   140 |   522	 (2)| 00
    :00:07 |
    
    |   1 |  SORT AGGREGATE 	    |	       |     1 |   140 |	    |
           |
    
    |*  2 |   HASH JOIN RIGHT OUTER     |	       |  2303 |   314K|   522	 (2)| 00
    :00:07 |
    
    |   3 |    INDEX FULL SCAN	    | I_USER2  |    99 |   396 |     1	 (0)| 00
    :00:01 |
    
    |*  4 |    HASH JOIN OUTER	    |	       |  2303 |   305K|   520	 (1)| 00
    :00:07 |
    
    |*  5 |     HASH JOIN OUTER	    |	       |  2303 |   287K|   461	 (2)| 00
    :00:06 |
    
    |*  6 |      HASH JOIN RIGHT OUTER  |	       |  2303 |   276K|   401	 (1)| 00
    :00:05 |
    
    |   7 |       TABLE ACCESS FULL     | SEG$     |  6267 | 68937 |    51	 (0)| 00
    :00:01 |
    
    |*  8 |       HASH JOIN 	    |	       |  2303 |   251K|   349	 (1)| 00
    :00:05 |
    
    |   9 |        TABLE ACCESS FULL    | TS$      |     7 |    21 |     4	 (0)| 00
    :00:01 |
    
    |  10 |        NESTED LOOPS	    |	       |  2303 |   245K|   345	 (1)| 00
    :00:05 |
    
    |  11 | 	MERGE JOIN CARTESIAN|	       |  2303 |   177K|   252	 (1)| 00
    :00:04 |
    
    |* 12 | 	 HASH JOIN	    |	       |     1 |    68 |     1 (100)| 00
    :00:01 |
    
    |* 13 | 	  FIXED TABLE FULL  | X$KSPPI  |     1 |    55 |     0	 (0)| 00
    :00:01 |
    
    |  14 | 	  FIXED TABLE FULL  | X$KSPPCV |   100 |  1300 |     0	 (0)| 00
    :00:01 |
    
    |  15 | 	 BUFFER SORT	    |	       |  2303 | 25333 |   252	 (1)| 00
    :00:04 |
    
    |* 16 | 	  TABLE ACCESS FULL | OBJ$     |  2303 | 25333 |   252	 (1)| 00
    :00:04 |
    
    |* 17 | 	TABLE ACCESS CLUSTER| TAB$     |     1 |    30 |     1	 (0)| 00
    :00:01 |
    
    |* 18 | 	 INDEX UNIQUE SCAN  | I_OBJ#   |     1 |       |     0	 (0)| 00
    :00:01 |
    
    |  19 |      INDEX FAST FULL SCAN   | I_OBJ1   | 73727 |   359K|    59	 (0)| 00
    :00:01 |
    
    |  20 |     INDEX FAST FULL SCAN    | I_OBJ1   | 73727 |   575K|    59	 (0)| 00
    :00:01 |
    
    --------------------------------------------------------------------------------
    --------
    
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("CX"."OWNER#"="CU"."USER#"(+))
       4 - access("T"."DATAOBJ#"="CX"."OBJ#"(+))
       5 - access("T"."BOBJ#"="CO"."OBJ#"(+))
       6 - access("T"."FILE#"="S"."FILE#"(+) AND "T"."BLOCK#"="S"."BLOCK#"(+) AND
    	      "T"."TS#"="S"."TS#"(+))
       8 - access("T"."TS#"="TS"."TS#")
      12 - access("KSPPI"."INDX"="KSPPCV"."INDX")
      13 - filter("KSPPI"."KSPPINM"='_dml_monitoring_enabled')
      16 - filter("O"."OWNER#"=USERENV('SCHEMAID') AND BITAND("O"."FLAGS",128)=0)
      17 - filter(BITAND("T"."PROPERTY",1)=0)
      18 - access("O"."OBJ#"="T"."OBJ#")
    
    
    Statistics
    ----------------------------------------------------------
    	 27  recursive calls
    	  0  db block gets
           1598  consistent gets
    	858  physical reads
    	  0  redo size
    	526  bytes sent via SQL*Net to client
    	523  bytes received via SQL*Net from client
    	  2  SQL*Net roundtrips to/from client
    	  1  sorts (memory)
    	  0  sorts (disk)
    	  1  rows processed
    You can lead some folks to knowledge, but you can not make them think.
    The average person thinks he's above average!
    For most folks, they don't know, what they don't know.
    Good judgement comes from experience. Experience comes from bad judgement.

  3. #3
    Join Date
    Feb 2004
    Location
    Wiessrussland
    Posts
    10
    tx,
    and still what unit this time showed in:
    time=48 us, I read somewhere about 10ms as a unit of time in Oracle, is it true?

    48 us = 48mSec??


    And for my case I need trace Procedure, how autotrace will work for sp.
    Tx
    D

  4. #4
    Join Date
    Aug 2003
    Location
    Where the Surf Meets the Turf @Del Mar, CA
    Posts
    7,776
    Provided Answers: 1
    I do not recognize what you posted.

    What OS name & version?

    post results from following SQL

    SELECT * from v$version;
    You can lead some folks to knowledge, but you can not make them think.
    The average person thinks he's above average!
    For most folks, they don't know, what they don't know.
    Good judgement comes from experience. Experience comes from bad judgement.

  5. #5
    Join Date
    Feb 2004
    Location
    Wiessrussland
    Posts
    10
    Tx, Anacedent !

    I have Oracle g10, I put trace=TRUE then somebody with server access did tkprof for me, so this is from there.


    Best
    Dai

  6. #6
    Join Date
    Aug 2003
    Location
    Where the Surf Meets the Turf @Del Mar, CA
    Posts
    7,776
    Provided Answers: 1
    below is from my test run which looks nothing like you posted

    Code:
    more v112_ora_6505.trc
    Trace file /u01/app/oracle/diag/rdbms/v112/v112/trace/v112_ora_6505.trc
    Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
    With the Partitioning, OLAP, Data Mining and Real Application Testing options
    ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
    System name:	Linux
    Node name:	bcm-laptop
    Release:	2.6.32-25-generic
    Version:	#44-Ubuntu SMP Fri Sep 17 20:05:27 UTC 2010
    Machine:	x86_64
    Instance name: v112
    Redo thread mounted by this instance: 1
    Oracle process number: 27
    Unix process pid: 6505, image: oracle@bcm-laptop (TNS V1-V3)
    
    
    *** 2010-10-19 21:07:09.800
    *** SESSION ID:(142.2166) 2010-10-19 21:07:09.800
    *** CLIENT ID:() 2010-10-19 21:07:09.800
    *** SERVICE NAME:(SYS$USERS) 2010-10-19 21:07:09.800
    *** MODULE NAME:(SQL*Plus) 2010-10-19 21:07:09.800
    *** ACTION NAME:() 2010-10-19 21:07:09.800
     
    =====================
    PARSING IN CURSOR #3 len=32 dep=0 uid=91 oct=42 lid=91 tim=1287547629799152 hv=1
    569151342 ad='7f930d4efe40' sqlid='4tk6t8tfsfqbf'
    alter session set sql_trace=true
    END OF STMT
    EXEC #3:c=0,e=430,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1287547629799133
    
    *** 2010-10-19 21:07:20.042
    CLOSE #3:c=0,e=28,dep=0,type=0,tim=1287547640042552
    =====================
    PARSING IN CURSOR #2 len=24 dep=0 uid=91 oct=3 lid=91 tim=1287547640087052 hv=23
    43063137 ad='b1785d78' sqlid='7h35uxf5uhmm1'
    select sysdate from dual
    END OF STMT
    PARSE #2:c=10000,e=44168,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1
    287547640087047
    EXEC #2:c=0,e=8881,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1287547
    640096347
    FETCH #2:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=12875476
    40096833
    STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us co
    st=2 size=0 card=1)'
    FETCH #2:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=128754764
    0098729
    
    *** 2010-10-19 21:07:24.354
    XCTEND rlbk=0, rd_only=1, tim=1287547644354747
    =====================
    PARSING IN CURSOR #3 len=447 dep=1 uid=0 oct=2 lid=0 tim=1287547644358286 hv=109
    7020010 ad='b1921c58' sqlid='f711myt0q6cma'
    insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,t
    erminal,action#,returncode, logoff$lread,logoff$pread,logoff$lwrite,logoff$dead,
     logoff$time,comment$text,spare1,clientid,sessioncpu,proxy$sid,user$guid, instan
    ce#,process#,auditid,dbid) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),     :4
    ,:5,:6,:7,:8,     :9,:10,:11,:12,     cast(SYS_EXTRACT_UTC(systimestamp) as date
    ),:13,:14,:15,:16,:17,:18,     :19,:20,:21,:22)
    END OF STMT
    PARSE #3:c=0,e=3127,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=128754764435828
    1
    EXEC #3:c=10000,e=5768,p=0,cr=1,cu=2,mis=1,r=1,dep=1,og=4,plh=0,tim=128754764436
    4772
    STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=
    0 time=0 us)'
    CLOSE #3:c=0,e=42,dep=1,type=0,tim=1287547644365229
    CLOSE #2:c=0,e=68,dep=0,type=0,tim=1287547644380293
    CLOSE #1:c=0,e=27,dep=0,type=0,tim=1287547644380505
    bcm@bcm-laptop:/u01/app/oracle/diag/rdbms/v112/v112/trace$ tkprof v112_ora_6505.trc
    output = /tmp/v112_ora_6505.txt
    
    TKPROF: Release 11.2.0.1.0 - Development on Tue Oct 19 21:08:42 2010
    
    Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
    
    
    bcm@bcm-laptop:/u01/app/oracle/diag/rdbms/v112/v112/trace$ more /tmp/v112_ora_6505.txt
    
    TKPROF: Release 11.2.0.1.0 - Development on Tue Oct 19 21:08:42 2010
    
    Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
    
    Trace file: v112_ora_6505.trc
    Sort options: default
    
    ********************************************************************************
    count    = number of times OCI procedure was executed
    cpu      = cpu time in seconds executing 
    elapsed  = elapsed time in seconds executing
    disk     = number of physical reads of buffers from disk
    query    = number of buffers gotten for consistent read
    current  = number of buffers gotten in current mode (usually for update)
    rows     = number of rows processed by the fetch or execute call
    ********************************************************************************
    
    SQL ID: 4tk6t8tfsfqbf
    Plan Hash: 0
    alter session set sql_trace=true
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        0      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        1      0.00       0.00          0          0          0           0
    
    Misses in library cache during parse: 0
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 91  
    ********************************************************************************
    
    SQL ID: 7h35uxf5uhmm1
    Plan Hash: 1388734953
    select sysdate 
    from
     dual
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.01       0.04          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.00       0.00          0          0          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.01       0.05          0          0          0           1
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 91  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
    
    ********************************************************************************
    
    SQL ID: f711myt0q6cma
    Plan Hash: 0
    insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,
      userhost,terminal,action#,returncode, logoff$lread,logoff$pread,
      logoff$lwrite,logoff$dead, logoff$time,comment$text,spare1,clientid,
      sessioncpu,proxy$sid,user$guid, instance#,process#,auditid,dbid) 
    values
    (:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),     :4,:5,:6,:7,:8,     :9,:10,:11,
      :12,     cast(SYS_EXTRACT_UTC(systimestamp) as date),:13,:14,:15,:16,:17,
      :18,     :19,:20,:21,:22)
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.01       0.00          0          1          2           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.01       0.00          0          1          2           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS   (recursive depth: 1)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  LOAD TABLE CONVENTIONAL  (cr=1 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.01       0.04          0          0          0           0
    Execute      2      0.00       0.00          0          0          0           0
    Fetch        2      0.00       0.00          0          0          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        5      0.01       0.05          0          0          0           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        1      0.00       0.00          0          0          0           0
    Execute      1      0.01       0.00          0          1          2           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.01       0.00          0          1          2           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    
        2  user  SQL statements in session.
        1  internal SQL statements in session.
        3  SQL statements in session.
    ********************************************************************************
    Trace file: v112_ora_6505.trc
    Trace file compatibility: 11.1.0.7
    Sort options: default
    
           1  session in tracefile.
           2  user  SQL statements in trace file.
           1  internal SQL statements in trace file.
           3  SQL statements in trace file.
           3  unique SQL statements in trace file.
          52  lines in trace file.
          14  elapsed seconds in trace file.
    
    
    bcm@bcm-laptop:/u01/app/oracle/diag/rdbms/v112/v112/trace$
    You can lead some folks to knowledge, but you can not make them think.
    The average person thinks he's above average!
    For most folks, they don't know, what they don't know.
    Good judgement comes from experience. Experience comes from bad judgement.

  7. #7
    Join Date
    Feb 2004
    Location
    Wiessrussland
    Posts
    10

    grubjet siology

    Tx, so let say for your case:

    tim=1287547629799133, what kind of this time format?


    Best
    Dai

  8. #8
    Join Date
    Nov 2003
    Posts
    2,935
    Provided Answers: 12
    Quote Originally Posted by DAINOVA View Post
    can anybody tell what is <time=31 us>
    us = Microseconds

    This is all described in the manual:
    http://download-uk.oracle.com/docs/cd/B19306_01/server.102/b14211/sqltrace.htm#i18110

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •