oracle@root:~/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
