10046 trace文件分析
Posted
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了10046 trace文件分析相关的知识，希望对你有一定的参考价值。
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 94912 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 128
1 96512 128
1 96640 128
1 96768 128
1 96896 128
25 rows selected.
SQL> alter session set events ‘10046 trace name context forever,level 12‘;
Session altered.
#没有创建索引，会走全表扫描
SQL> select count(*) from t10046;
COUNT(*)
----------
86956
SQL> alter session set events ‘10046 trace name context off‘;
trace文件内容：
===================== PARSING IN CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad=‘7bf41070‘ sqlid=‘awzvq6b3da pqt‘ select count(*) from t10046 END OF STMT PARSE #140231913930616:c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403 EXEC #140231913930616:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292551 WAIT #140231913930616: nam=‘SQL*Net message to client‘ ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1458364346292607 WAIT #140231913930616: nam=‘enq: KO - fast object checkpoint‘ ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=145836434629669 1 WAIT #140231913930616: nam=‘direct path read‘ ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284 WAIT #140231913930616: nam=‘direct path read‘ ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150 WAIT #140231913930616: nam=‘direct path read‘ ela= 912 file number=1 first dba=95872 block cnt=128 obj#=88635 tim=1458364346300730 WAIT #140231913930616: nam=‘direct path read‘ ela= 386 file number=1 first dba=96000 block cnt=128 obj#=88635 tim=1458364346301893 WAIT #140231913930616: nam=‘direct path read‘ ela= 299 file number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928 WAIT #140231913930616: nam=‘direct path read‘ ela= 371 file number=1 first dba=96256 block cnt=128 obj#=88635 tim=1458364346304307 WAIT #140231913930616: nam=‘direct path read‘ ela= 236 file number=1 first dba=96384 block cnt=128 obj#=88635 tim=1458364346305513 WAIT #140231913930616: nam=‘direct path read‘ ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513 WAIT #140231913930616: nam=‘direct path read‘ ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527 WAIT #140231913930616: nam=‘direct path read‘ ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125 WAIT #140231913930616: nam=‘direct path read‘ ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304 FETCH #140231913930616:c=14998,e=19124,p=1240,cr=1243,cu=0,mis=0,r=1,dep=0,og=1,plh=2130400753,tim=1458364346311758 STAT #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 #140231913930616: 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=1458364346312405 WAIT #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.876 WAIT #140231913930616: nam=‘SQL*Net message from client‘ ela= 11563756 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=14583643578 76195 CLOSE #140231913930616:c=0,e=10,dep=0,type=0,tim=1458364357876316 =====================
trace文件分析：
1.数据库调用
含3个子分类：解析，执行和获取
这3个分类与通过调用DBMS_SQL的子例程DBMS_SQL.PARSE,DBMS_SQL.EXECUTE,DBMS_SQL.FETCH_ROWS来跑SQL的步调相一致
解析在跟踪文件中通常通过两个相邻的条目表示：第一个是PARSING IN CURSOR,第二个是PARSE。如下所示：
PARSING IN CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad=‘7bf41070‘ sqlid=‘awzvq6b3da pqt‘ select count(*) from t10046 END OF STMT PARSE #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各项的具体含义
| 参数 | 说明 |
| len |
表示sql语句文本字节长度 #"select count(*) from t10046"字节长度为27 |
| dep |
递归调用深度 #本次调用深度为0 |
| uid |
解析用户标识符，对应于all_users.user_id以及v$sql.parsing_user_id #本次是以sys用户执行的，故uid=0 |
| oct |
oracle命令类型，对应于v$sql.command_type以及v$session.command #select对应类型是3 |
| lid | 解析模式标识符，对应于all_users.user_id以及v$sql.parsing_schema_id，可能与uid不同 |
| tim | 微秒单位时间戳，在关联的parse条目中通常比tim的值早一点 |
| hv | 哈希值，对应于v$sql.hash_value |
| ad | address，对应于v$sql.address |
| sqlid | sql id，对应与v$sql.sql_id |
对应的trace文件：
$ tkprof /u01/app/oracle/diag/rdbms/db11/db11/trace/db11_ora_3959.trc 4.txt
$ more 4.txt
TKPROF: Release 11.2.0.4.0 - Development on Sat Mar 19 13:14:12 2016
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/oracle/diag/rdbms/db11/db11/trace/db11_ora_3959.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: 96g93hntrzjtr Plan Hash: 2239883476
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
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 1 0.00 0.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 2 0 0
Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
SQL ID: cg2uxaa74kbrs Plan Hash: 1492740290
SELECT /* 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") SAMPLESUB
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 217 56 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 217 58 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS (recursive depth: 1)
Number of plan statistics captured: 1
Rows (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 include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 11 0.00 0.00
db file scattered read 27 0.00 0.00
********************************************************************************
SQL ID: awzvq6b3dapqt Plan Hash: 2130400753
select count(*)
from
t10046
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.01 1240 1243 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.02 1240 1244 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us)
86956 86956 86956 TABLE ACCESS FULL T10046 (cr=1243 pr=1240 pw=0 time=24549
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 11 0.00 0.00
SQL*Net message from client 2 11.56 11.56
********************************************************************************
SQL ID: 06nvwn223659v Plan Hash: 0
alter session set events ‘10046 trace name context off‘
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 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 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: SYS
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 1 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.01 1240 1243 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.02 1240 1244 0 1
Misses in library cache during parse: 1
Elapsed 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 11 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 2 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 217 58 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 217 60 0 1
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 11 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.trc
Trace file compatibility: 11.1.0.7
Sort 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.
11 elapsed seconds in trace file.
$
以上是关于10046 trace文件分析的主要内容，如果未能解决你的问题，请参考以下文章