Tkprof工具详解一（转载）

Posted 2020-10-26 youngerger

在数据库生成的oracle trace文件中，可读性是比较差的，此时可使用tkprof工具来格式化trace文件，tkprof是一个命令行工具，作用就是把原始的跟踪trace文件作为输入，然后格式化一个可读性比较好的文本文件。

在下面的例子中，输入文件是 ora11g_ora_3918.trc，输出文件是test.log

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42

[email protected]:~/diag/rdbms/orcl/ora11g/trace> tkprof ora11g_ora_3918.trc test.log   TKPROF: Release 11.2.0.1.0 - Development on Sat Jun 22 11:38:40 2013   Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.   下面我们来了解一下tkprof的参数，直接敲tkprof命令即可查看参数： [email protected]:~/diag/rdbms/orcl/ora11g/trace> tkprof Usage: tkprof tracefile outputfile [explain= ] [table= ]               [print= ] [insert= ] [sys= ] [sort= ]   table=schema.tablename   Use ‘schema.tablename‘ with ‘explain=‘ option.   explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.   print=integer    List only the first ‘integer‘ SQL statements.   aggregate=yes|no   insert=filename  List SQL statements and data inside INSERT statements.   sys=no           TKPROF does not list SQL statements run as user SYS.   record=filename  Record non-recursive statements found in the trace file.   waits=yes|no     Record summary for any wait events found in the trace file.   sort=option      Set of zero or more of the following sort options:     prscnt  number of times parse was called     prscpu  cpu time parsing     prsela  elapsed time parsing     prsdsk  number of disk reads during parse     prsqry  number of buffers for consistent read during parse     prscu   number of buffers for current read during parse     prsmis  number of misses in library cache during parse     execnt  number of execute was called     execpu  cpu time spent executing     exeela  elapsed time executing     exedsk  number of disk reads during execute     exeqry  number of buffers for consistent read during execute     execu   number of buffers for current read during execute     exerow  number of rows processed during execute     exemis  number of library cache misses during execute     fchcnt  number of times fetch was called     fchcpu  cpu time spent fetching     fchela  elapsed time fetching     fchdsk  number of disk reads during fetch     fchqry  number of buffers for consistent read during fetch     fchcu   number of buffers for current read during fetch     fchrow  number of rows fetched     userid  userid of user that parsed the cursor

explain：参数格式为explain=username/[email protected]_name 或者explain=username/password，这个参数是通过执行explain plan语句来做到的，在trace文件中找到每个sql语句，提供一个执行计划。一般不是必要情况，指定这个参数并不可取，一旦指定了无效的信息，在输出的文件就会出现error。

table：table参数只和explain参数一起使用，用来指定某个表被explain plan语句使用来生成执行计划，通常尽量避免使用table参数，这里就不详细说明不常用的参数了，大家想要了解的话，可以查看oracle的官方联机文档。

print：参数用来限制输出文件生成的sql语句的数量，默认是无限制的。eg：只输出10个sql语句，则参数指定print=10，一般和sort参数一起使用才具有一定的意义。

insert：生成sql脚本，脚本可以用来把数据存储到数据库中。eg：insert=load_data.sql 。

sys：参数执行sys用户下运行的sql语句是否写入到输出文件，默认为yes。可设置为no，避免输出不必要的信息，这个看情况而定吧。

sort：排序的意思，指定输出文件里面的sql语句的顺序，默认是trace源文件里面的sql顺序。你可以指定根据cpu时间，物理读的块数，调用次数等进行排序，eg：sort=elapsed,disk   —多个排序用逗号隔开。

aggregate：参数指定是否合并相同的sql，默认为yes，设置为no，输出文件就会列出每个sql的消耗情况等信息。

用得比较多的一般是sys和aggregate参数。

下面我们来简单分析一下经过tkprof工具格式化处理过的trace文件：

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84

[email protected]:~/diag/rdbms/orcl/ora11g/trace> more mount_open.log --头部内容，这里可以看到trace源文件，sort参数等信息 TKPROF: Release 11.2.0.1.0 - Development on Fri Jun 21 14:00:51 2013   Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.   Trace file: /opt/oracle/diag/rdbms/orcl/ora11g/trace/ora11g_ora_14009.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的信息：sql文本，统计信息，解析信息，执行计划，等待事件等。 ********************************************************************************   SQL ID: 0cmnx32jn5wsp Plan Hash: 1876228229 CREATE INDEX I_OBJ# ON CLUSTER C_OBJ# PCTFREE 10 INITRANS 2 MAXTRANS 255   STORAGE (  INITIAL 64K NEXT 1024K MINEXTENTS 1 MAXEXTENTS 2147483645   PCTINCREASE 0 OBJNO 3 EXTENTS (FILE 1 BLOCK 168))   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   count：执行的数据库调用数量，也就是当前操作执行的次数 cpu：处理数据花费的cpu时间，单位是秒 elapsed：当前操作花费的总用时，包括cpu时间和等待时间，单位是秒 disk：物理读的数据库数量 query：当前操作的一致性模式读取的数据块数，通常是查询 current：当前操作读取的数据块数，通常是修改数据，比如insert ，update，delete等语句所使用的。 rows：当前操作处理的数据行数   Misses in library cache during parse: 1------表示shared pool没有命中，这是一次硬分析，软分析这里为0 Optimizer mode: CHOOSE   -----当前的优化模式 Parsing user id: SYS   (recursive depth: 1)  ---当前处理的对象   Rows     Row Source Operation -------  ---------------------------------------------------       0  INDEX BUILD UNIQUE I_OBJ# (cr=0 pr=0 pw=0 time=0 us)(object id 0)       0   SORT CREATE INDEX (cr=0 pr=0 pw=0 time=0 us cost=0 size=0 card=0)       0    TABLE ACCESS FULL C_OBJ# (cr=0 pr=0 pw=0 time=0 us)   rows：表示当前操作返回的数据条数 Row Source Operation：行源操作，表示当前数据的访问方式 cr：一致性方式读取的数据块数，相当于query列上的fetch步骤的值 pr：物理读的数据块，相当于disk列上的fetch步骤的值 pw：物理写入磁盘的数据块数 time：以微秒表示的总的消逝时间 cost：操作的评估开销 size：操作返回的预估数据量，单位是字节 card：操作返回的语句行数   注意：这些值除了card之外，都是累计的。 ********************************************************************************   此外trace文件有很多内容值得探索，这里基础就不体现了。   下面来看一下原始sql_trace生成的原始trace文件，没有经过tkprof处理 PARSING IN CURSOR #4 len=35 dep=0 uid=85 oct=3 lid=85 tim=1371272962082555 hv=4042069092 ad=‘7e2769c0‘ sqlid=‘6xxmr xrsfu534‘ select * from t where object_id=345 END OF STMT PARSE #4:c=0,e=2120,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3745387144,tim=1371272962082553 EXEC #4:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3745387144,tim=1371272962082705 FETCH #4:c=0,e=5486,p=5,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3745387144,tim=1371272962088298 FETCH #4:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=3745387144,tim=1371272962094265 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=73517 op=‘TABLE ACCESS BY INDEX ROWID T (cr=4 pr=5 pw=0 time=0 us cost=2 size=29 card=1)‘ STAT #4 id=2 cnt=1 pid=1 pos=1 obj=73518 op=‘INDEX RANGE SCAN BIN$3x4G/ATIcRfgQKjAgpEWgw==$0 (cr=3 pr=5 pw=0 time=0 us cost=1 size=0 card=1)‘ *** 2013-06-15 01:09:36.832 CLOSE #4:c=0,e=40,dep=0,type=0,tim=1371272976832430

 oracle会首先对这条sql语句作分析，并且有一个游标号：CURSOR #4，这个号在整个trace文件中不是唯一的，当一条sql语句执行结束后，这个号被重用
我们还可以看到这条sql语句被分析了一次，执行了一次，fetch了2次，STAT#4是对这条sql语句执行过程中的资源消耗统计，trace文件中信息的输出顺序就是sql语句执行的顺序，通过这些顺序，就可以知道sql语句是如果执行的

PARSING IN CURSOR 部分：
len：被分析sql的长度
dep：产生递归sql的深度
uid：userid
otc：oracle command type命令的类型
lid：私有的用户id
tim：时间戳
hv：hash value
ad：sql address

PARSE, EXEC, FETCH部分：
c：消耗的cpu time
e：elapsed time操作用时
p：physical reads物理读的次数
cr：consistent reads一致性方式读取的数据块数
cu：current方式读取的数据块数
mis：cursor miss in cache 硬分析的次数
r：rows处理的行数
dep：depth递归sql的深度
og：optimizer goal优化器模式
tim：timestamp 时间戳

STAT部分：
id：执行计划的行源号
cnt：当前行源返回的行数
pid：当前行源号的父号
pos：当前操作的对象id，如果当前行原始一个对象的话
op：当前行源的数据访问操作