10046 Trace File Analysis

Sql> CREATE TABLE t10046 as SELECT * from Dba_objects; Table created.   Sql> Select File_id,block_id,blocks from dba_extents where segment_name= ' T10046 ';          file_id block_id BLOCKS------------------------------1 94664 8 1 94672          8 1 94680 8 1 94688 8 1 94696 8 1 94704 8 1 94712 8 1 94896 8 1 94904 8 1 9      4912 8 1 94920 8 1 94928 8 1 94936 8 1         94944 8 1 94952 8 1 94960 8 1 95872 128 1 96000 128 1 96128 128 1 96256 128 1 96384 12   8 1 96512 128 1 96640 128 1 96768 128 1   96896 12825 rows selected. Sql> alter session SET events ' 10046 Trace name context forever,level 12 ';  Session altered. #没有创建索引, will walk full table scan sql> select COUNT (*) from t10046; COUNT (*)----------86956sql> alter session set events ' 10046 Trace name context off ';

Trace file Contents:

=====================parsing in CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv= 3335870169 ad= ' 7bf41070 ' sqlid= ' awzvq6b3dapqt ' select COUNT (*) from T10046end of Stmtparse #140231913930616: c=10998,e= 11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403exec #140231913930616: C=0,e=36,p =0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292551wait #140231913930616: nam= ' SQL*Net message To client ' Ela= 7 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1458364346292607wait #140231913930616: nam= ' Enq:ko-fas T object checkpoint ' ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=1458364346296691wait #140231913930616: nam= ' d  Irect path read ' ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284wait #140231913930616: nam= ' direct path read ' ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150wait #14023191 3930616:nam= ' direct path read ' ela= 912 file number=1 Firstdba=95872 block cnt=128 obj#=88635 tim=1458364346300730wait #140231913930616: nam= ' direct path read ' ela= 386 file number=  1 First dba=96000 block cnt=128 obj#=88635 tim=1458364346301893wait #140231913930616: nam= ' direct path read ' ela= 299 file Number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928wait #140231913930616: nam= ' direct path read ' ela= 371 file number=1 First dba=96256 block cnt=128 obj#=88635 tim=1458364346304307wait #140231913930616: nam= ' direct path rea d ' ela= 236 file number=1 First dba=96384 block cnt=128 obj#=88635 tim=1458364346305513wait #140231913930616: nam= ' direct Path read ' ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513wait #140231913930616: nam= ' Direct path read ' ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527wait #1402319139306 16:nam= ' direct path read ' ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125wait #14023 1913930616:nam= ' DirectPath read ' ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304fetch #140231913930616: c=149 98,e=19124,p=1240,cr=1243,cu=0,mis=0,r=1,dep=0,og=1,plh=2130400753,tim=1458364346311758stat #140231913930616 id= 1 cnt=1 pid=0 pos=1 obj=0 op= ' SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us) ' STAT #140231913930616 id=2 cnt=86956 pid =1 pos=1 obj=88635 op= ' TABLE ACCESS full T10046 (cr=1243 pr=1240 pw=0 time=24549 US cost=338 size=0 card=70030) ' WAIT #1402 31913930616:nam= ' sql*net message from client ' ela= 225 driver id=1650815232 #bytes =1 p3=0 obj#=88635 tim=1458364346312363 FETCH #140231913930616: C=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2130400753,tim=1458364346312405wait # 140231913930616:nam= ' sql*net message to client ' Ela= 2 driver id=1650815232 #bytes =1 p3=0 obj#=88635 tim=1458364346312426 2016-03-19 13:12:37.876wait #140231913930616: nam= ' sql*net message from client ' ela= 11563756 driver id=1650815232 #by Tes=1 p3=0 obj#=88635 Tim=1458364357876195close #140231913930616:c=0,e=10,dep=0,type=0,tim=1458364357876316===================== 

Trace File Analysis:

1. Database invocation
With 3 subcategories: parsing, execution, and acquisition
These 3 classifications are associated with subroutine Dbms_sql by calling Dbms_sql. Parse,dbms_sql. Execute,dbms_sql. Fetch_rows to run at the same pace as SQL.
Parsing is typically represented by two adjacent entries in a trace file: The first is the parsing in CURSOR and the second is parse. As shown below:

Parsing in CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad= ' 7bf41070 ' sqlid= ' AWZVQ6B3DAPQT ' SELECT COUNT (*) from T10046end of Stmtparse #140231913930616: c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r= 0,dep=0,og=1,plh=2130400753,tim=1458364346292403

Parsing in cursor the specific meaning of each item

Parameters	Description
Len	Represents the SQL statement text byte length # "SELECT COUNT (*) from t10046" byte length is 27
Dep	Recursive call depth #本次调用深度为0
Uid	Resolves user identifiers, corresponding to all_users.user_id and v$sql.parsing_user_id #本次是以sys用户执行的, so Uid=0
Oct	Oracle command type, corresponding to V$sql.command_type and V$session.command #select对应类型是3
Lid	Parse pattern identifier, corresponding to all_users.user_id and v$sql.parsing_schema_id, may differ from UID
Tim	Microsecond unit timestamp, usually a little earlier than the value of Tim in the associated parse entry
Hv	hash value, corresponding to V$sql.hash_value
Ad	Address, corresponding to v$sql.address
Sqlid	SQL ID, corresponding to v$sql.sql_id

The corresponding trace file:

$ tkprof/u01/app/oracle/diag/rdbms/db11/db11/trace/db11_ora_3959.trc 4.txt$ more 4.txttkprof:release 11.2.0.4.0-  Development on Sat 13:14:12 2016Copyright (c) 1982, and Oracle and/or its affiliates. All rights reserved. Trace file:/u01/app/oracle/diag/rdbms/db11/db11/trace/db11_ora_3959.trcsort options:default*********************  Count = number of times OCI procedure was EXECUTEDCPU = CPU time in seconds executing elapsed = elapsed time in seconds Executingdisk = number of physical reads of buffers From diskquery = number of buffers gotten for consistent readcurrent = number of buffers gotten in current mode (usual ly for update) rows = number of rows processed by the fetch or execute call******************************************** SQL id:96g93hntrzjtr Plan hash:2239883476select/*+ rule */bucket_cnt, ROW_CNT, CA Che_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, Spare1, Spare2, Avgcln from hist_head$ where Obj#=:1 and INTC Ol#=:2call count CPU Elapsed disk query current rows-------------------------------           ----------------------------------------Parse 0 0.00 0.00 0 0 0          0Execute 1 0.00 0.00 0 0 0 0Fetch 1 0.00 0.00 0 2 0 0-----------------------------------------------------------------------to Tal 2 0.00 0.00 0 2 0 0Misses in library cache during Parse:0optim Izer mode:ruleparsing User Id:sys (recursive depth:2) **************************************************************   SQL Id:cg2uxaa74kbrs Plan hash:1492740290select/* opt_dyn_samp *//*+ all_rows Ignore_where_clause No_parallel (samplesub) opt_param (' parallel_execution_enabled ', ' false ') No_parallel_index (samplesub) No_sql_tune */NVL (sum (C1), 0), NVL (SUM (C2 ), 0) from (select/*+ no_parallel ("T10046") Full ("T10046") No_parallel_index ("T10046") */1 as C1, 1 as C2 from "SYS". " T10046 "SAMPLE BLOCK (5.080645, 1) SEED (1)" T10046 ") Samplesubcall count CPU elapsed Disk Quer      Y current rows-----------------------------------------------------------------------Parse 1          0.00 0.00 0 2 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 1 0.00 0.00 217 0 1-------------------          ----------------------------------------------------Total 3 0.00 0.00 217 58 0 1Misses in library cache during Parse:1optimizer mode:all_rowsparsing user Id:sys (recursive depth:1) Number of plan statistics capTured:1rows (1st) rows (avg) rows (max) Row Source operation--------------------------------------------------------       -------------------------1 1 1 SORT AGGREGATE (cr=56 pr=217 pw=0 time=6918 us) 3558 3558 3558 TABLE ACCESS SAMPLE T10046 (cr=56 pr=217 pw=0 time=1672 US cost=19 size=61752 card=5146) Elapsed times I Nclude waiting on following events:event waited on Times Max.                        Wait Total waited----------------------------------------waited----------------------db file sequential read          0.00 0.00 DB File Scattered read 27 0.00 0.00********************************************************************************sql ID:AWZVQ6B3DAPQT Plan Hash:2130400753select Count (*) from T10046call count CPU elapsed disk query current row s-----------------------------------------------------------------------Parse 1 0.00 0.00 0 1 0 0Execute 1 0.0          0 0.00 0 0 0 0Fetch 2 0.01 0.01 1240 1243       0 1-----------------------------------------------------------------------Total 4 0.01 0.02 1240 1244 0 1Misses in library cache during Parse:1optimizer Mode:all_rowsparsin G User Id:sysnumber of Plan statistics captured:1rows (1st) rows (avg) rows (max) Row Source Operation---------------- -----------------------------------------------------------------1 1 1 SORT AGGREGATE (cr=1 243 pr=1240 pw=0 time=19122 us) 86956 86956 86956 TABLE ACCESS full T10046 (cr=1243 pr=1240 pw=0 time=2454                             9 US cost=338 size=0 card=70030) Elapsed times include waiting on following Events:event waited on Times Max. Wait Total waited----------------------------------------waited----------------------sql*net message to Client   2 0.00 0.00 Enq:ko-fast Object Checkpoint 1 0.00 0.00                     Direct Path Read 0.00 0.00 Sql*net Message from client 2 11.56 11.56********************************************************************************sql id:06 nvwn223659v Plan hash:0alter Session Set Events ' 10046 Trace name context off ' call count CPU elapsed D         ISK query Current rows-----------------------------------------------------------------------Parse          1 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 0 0.00 0.00 0 0 0 0-------- -----  -------- --------------------------------------------------Total 2 0.00 0.00 0 0 0 0Misses in library cache during parse:0parsing user id:sys********************************************************** OVERALL TOTALS for all non-recursive statementscall count CPU elapsed Disk Q      Uery Current rows-----------------------------------------------------------------------Parse 2           0.00 0.00 0 1 0 0Execute 2 0.00 0.00 0 0 0 0Fetch 2 0.01 0.01 1240 1243 0 1----------------          -------------------------------------------------------Total 6 0.01 0.02 1240 1244  0 1Misses in library cache during parse:1elapsed times include waiting on following Events:event waited                     On        Times Max.                        Wait Total waited----------------------------------------waited----------------------sql*net message to Client         3 0.00 0.00 Sql*net Message from client 3 16.70                               28.27 Enq:ko-fast Object Checkpoint 1 0.00 0.00 Direct Path Read       0.00 0.00OVERALL TOTALS for all RECURSIVE statementscall count CPU Elapsed Disk query Current rows-----------------------------------------------------------------------Pars           E 1 0.00 0.00 0 2 0 0Execute 2 0.00 0.00 0 0 0 0Fetch 2 0.00 0.00 217 0 1-------       ----------------------------------------------------------------Total 5 0.00 0.00 217  0 1Misses in library cache during parse:1elapsed times include waiting on following Events:even T waited on Times Max.                        Wait Total waited----------------------------------------waited----------------------db file sequential read          0.00 0.00 DB File Scattered read 27 0.00    0.00 2 User SQL statements in session.    2 internal SQL statements in session. 4 SQL Statements in Session.********************************************************************************trace File:/u01/app/oracle/diag/rdbms/db11/db11/trace/db11_ora_3959.trctrace file Compatibility:11.1.0.7sort options:       Default 1 session in Tracefile.       2 user SQL statements in trace file.       2 internal SQL statements in trace file.       4 SQL statements in trace file.     4 unique SQL statements in trace file.      133 lines in trace file. ElapseD seconds in Trace file.$  

10046 Trace File Analysis