使用10046 trace跟踪SQL 的方法，请参考文章 https://blog.csdn.net/u010692693/article/details/75765958
生成的trace文件 /oracle/app/oracle/diag/rdbms/orarpt/orarpt2/trace/orarpt2_ora_6573.trc
数据库和操作系统版本信息
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /oracle/app/oracle/product/11.2.0.3/dbhome_1
System name: Linux
Node name: db02
Release: 2.6.32-400.35.2.el5uek
Version: #1 SMP Thu Feb 13 15:00:30 PST 2014
Machine: x86_64
Instance name: orarpt2
Redo thread mounted by this instance: 2
Oracle process number: 61
Unix process pid: 6573, image: oracle@db02 (TNS V1-V3)内容
WAIT #140337483410544: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573715436251654
--SQL*Net message to client 数据库准备向客户端发送指令 非空闲等待
--nam 等待事件
--ela 此操作消耗的时间 单位(微秒)
--p3 block 块号
--obj# dba_objects(object_id)
--trm timestamp 时间戳
WAIT #140337483410544: nam='SQL*Net message from client' ela= 6745728 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573715442998136
--SQL*Net message from client 等待客户端向服务器发送指令 空闲等待
PARSING IN CURSOR #140337483403688 len=210 dep=1 uid=0 oct=3 lid=0 tim=1573715443025593 hv=864012087 ad='9f5e0b1a8' sqlid='96g93hntrzjtr'
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
END OF STMT
PARSE #140337483403688:c=0,e=102,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1573715443025593
BINDS #140337483403688:
Bind#0 --绑定变量 obj#=:1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=00 fl2=0001 frm=00 csi=00 siz=48 off=0
kxsbbbfp=7fa2ddd8b520 bln=22 avl=05 flg=05
value=2994904 --obj#=:1的值
Bind#1 --绑定变量 intcol#=:2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=00 fl2=0001 frm=00 csi=00 siz=0 off=24
kxsbbbfp=7fa2ddd8b538 bln=22 avl=02 flg=01
value=2 --intcol#=:2的值
EXEC #140337483403688:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1573715443025757
FETCH #140337483403688:c=0,e=40,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1573715443025810
STAT #140337483403688 id=1 cnt=0 pid=0 pos=1 obj=425 op='TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=43 us)'
STAT #140337483403688 id=2 cnt=0 pid=1 pos=1 obj=427 op='INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=3 pr=0 pw=0 time=39 us)'
CLOSE #140337483403688:c=0,e=2,dep=1,type=3,tim=1573715443025856
--从上面的 trace 文件我们可以看出 SQL 语句经过了 PARSING(解析) -> EXEC(执行) -> FETCH(从游标中获取数据) 几个过程,
--PARSING 解析
--CURSOR cursor id 临时的，可能会被重用
--len SQL 语句长度(字节)
--dep SQL 语句递归深度 =0表示没有做递归调用
--uid dba_users(user_id) =0表示是SYS用户
--oct oracle command type(命令类型) =3表示是SELECT SELECT command_name FROM v$sqlcommand WHERE command_type = 3;
--lid privilege user id
--tim timestamp，时间戳
--hv SQL hash value
--ad SQL address 地址, 用在 v$sqltext
--sqlid SQL ID
--EXEC 执行
--c CPU 消耗的时间
--e Elapsed time
--p number of physical reads 物理读的次数
--cr number of buffers retrieved for CR reads 逻辑读的数据块
--cu number of buffers retrieved in current mode (current 模式读取的数据块)
--mis cursor missed in the cache 库缓存中丢失的游标, 硬解析次数 =1表示发生硬解析，0表示软解析
--r number of rows processed 处理的行数
--dep 递归调用次数
--og optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】
--plh plan hash value
--tim timestamp 时间戳
=====================
PARSING IN CURSOR #140337483405144 len=54 dep=0 uid=432 oct=3 lid=432 tim=1573715443026172 hv=145685581 ad='9b58a6110' sqlid='1ys4wc84axz2d'
select object_id,object_name from t where object_id<10
END OF STMT
PARSE #140337483405144:c=19997,e=27919,p=1,cr=90,cu=0,mis=1,r=0,dep=0,og=1,plh=4182247035,tim=1573715443026171
EXEC #140337483405144:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4182247035,tim=1573715443026223
WAIT #140337483405144: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573715443026243
FETCH #140337483405144:c=0,e=29,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=4182247035,tim=1573715443026290
WAIT #140337483405144: nam='SQL*Net message from client' ela= 191 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573715443026511
WAIT #140337483405144: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573715443026550
FETCH #140337483405144:c=0,e=30,p=0,cr=2,cu=0,mis=0,r=7,dep=0,og=1,plh=4182247035,tim=1573715443026569
STAT #140337483405144 id=1 cnt=8 pid=0 pos=1 obj=2994904 op='TABLE ACCESS BY INDEX ROWID T (cr=5 pr=0 pw=0 time=27 us cost=3 size=632 card=8)'
STAT #140337483405144 id=2 cnt=8 pid=1 pos=1 obj=2995355 op='INDEX RANGE SCAN IND_T_ID (cr=3 pr=0 pw=0 time=43 us cost=2 size=0 card=8)'
*** 2019-11-14 15:10:50.952
WAIT #140337483405144: nam='SQL*Net message from client' ela= 7925505 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573715450952121
CLOSE #140337483405144:c=0,e=8,dep=0,type=0,tim=1573715450952194
=====================
--STAT 执行计划
--cnt 返回的行数
--pid parent id of this row source 当前行源的父结点 id
--pos position in explain plan 执行计划的位置
--obj object id of row source (if this is a base object)
--op the row source access operation
--op
--cr 逻辑读
--pr 物理读
--pw 物理写
--time 消耗时间(us)
--cost 成本
--size 返回记录大小(B)
--card 返回记录数TKprof，TRACE文件格式化工具
tkprof /oracle/app/oracle/diag/rdbms/orarpt/orarpt2/trace/orarpt2_ora_6573.trc /home/oracle/orarpt2_ora_6573.log
********************************************************************************
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: 1ys4wc84axz2d Plan Hash: 4182247035
select object_id,object_name
from
t where object_id<10
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.02 1 90 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 5 0 8
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.02 1 95 0 8
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 432
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
8 8 8 TABLE ACCESS BY INDEX ROWID T (cr=5 pr=0 pw=0 time=27 us cost=3 size=632 card=8)
8 8 8 INDEX RANGE SCAN IND_T_ID (cr=3 pr=0 pw=0 time=43 us cost=2 size=0 card=8)(object id 2995355)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 3 0.00 0.00
row cache lock 1 0.00 0.00
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 7.92 7.92
********************************************************************************
--cr 逻辑读
--pr 物理读
--pw 物理写
--time 消耗时间(us)
--cost 成本
--size 返回记录大小(B)
--card 返回记录数TRCANLZR (TRCA) SQL_TRACE/10046事件trace文件分析器
请参考文章：https://blog.csdn.net/u010692693/article/details/103072575
432
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
