10046 Trace File Analysis

Source: Internet
Author: User

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

Contact Us

The content source of this page is from Internet, which doesn't represent Alibaba Cloud's opinion; products and services mentioned on that page don't have any relationship with Alibaba Cloud. If the content of the page makes you feel confusing, please write us an email, we will handle the problem within 5 days after receiving your email.

If you find any instances of plagiarism from the community, please send an email to: info-contact@alibabacloud.com and provide relevant evidence. A staff member will contact you within 5 working days.

A Free Trial That Lets You Build Big!

Start building with 50+ products and up to 12 months usage for Elastic Compute Service

  • Sales Support

    1 on 1 presale consultation

  • After-Sales Support

    24/7 Technical Support 6 Free Tickets per Quarter Faster Response

  • Alibaba Cloud offers highly flexible support services tailored to meet your exact needs.