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文件分析的主要内容,如果未能解决你的问题,请参考以下文章

Oracle 10046事件 介绍 ---tkprof

使用 10046 查看执行计划并读懂 trace 文件

[Oracle]如何查看 10046 trace 中的 tim= ... 的具体时刻

经典10046剖析案例-4

10046 trace详解--tkprof

Oracle SQL Trace 和 10046 事件