一、开篇当AWR报告不够用时某天DBA通过AWR报告发现一条SQL消耗了大量资源但AWR报告只能看到汇总数据——这条SQL执行了1000次总耗时8000秒。font color#D32F2F但AWR无法告诉你这1000次执行中是每次都很慢还是个别几次慢时间花在解析上还是执行上是CPU等待还是I/O等待/fontfont color#1976D2这时候就需要SQL Trace出马。SQL Trace是Oracle最底层的SQL执行追踪工具可以记录SQL执行的每一个步骤——每次解析、每次I/O、每次等待事件精确到微秒级。/font本篇文章从10046事件启用、Trace文件解读、TKPROF格式化分析到实战诊断案例全面覆盖SQL Trace和TKPROF的使用技巧。二、SQL Trace架构全景图诊断应用格式化分析Trace文件生成追踪启用方式SQL Trace启用10046事件-当前会话DBMS_MONITOR-指定会话SQL Hint-MONITORuser_dump_dest目录V$SQL_MONITOR视图.trc原始Trace文件TKPROF格式化trcsess会话合并Trace Analyzer工具格式化报告.txtParse/Exec/Fetch耗时等待事件时间线逻辑读/物理读统计行源操作耗时关键解读font color#D32F2F红色10046事件/font 最常用的会话级追踪方式。font color#F57C00橘色Trace文件/font 原始追踪数据人类难以直接阅读。font color#388E3C绿色TKPROF/font 将Trace文件转换为可读的汇总报告。三、SQL Trace的启用方式1. font color#D32F2F10046事件最经典的追踪方式/font10046事件的级别| Level | 追踪内容 | 使用场景 ||-------|----------|----------|| 1 | 标准SQL Trace | 基本SQL执行信息 || 4 | Level 1 绑定变量值 | 需要查看绑定变量值 || 8 | Level 1 等待事件 | 需要分析等待事件 || 12 | Level 1 绑定变量 等待事件 | font color#388E3C最常用推荐级别/font |启用10046事件-- 对当前会话启用Level 12 ALTER SESSION SET EVENTS 10046 trace name context forever, level 12; -- 执行需要追踪的SQL SELECT * FROM orders WHERE order_id 100; -- 关闭10046事件 ALTER SESSION SET EVENTS 10046 trace name context off; -- 找到生成的Trace文件 SELECT value FROM v$diag_info WHERE name Default Trace File;2. font color#1976D2DBMS_MONITOR无需修改代码的追踪/font-- 获取目标会话的SID和SERIAL# SELECT sid, serial#, username, program FROM v$session WHERE username SCOTT; -- 启用追踪包含等待事件和绑定变量 EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE( session_id 123, serial_num 45678, waits TRUE, binds TRUE ); -- 关闭追踪 EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE( session_id 123, serial_num 45678 );3. font color#F57C00按服务/模块/操作追踪/font-- 应用代码中设置模块和操作 BEGIN DBMS_APPLICATION_INFO.SET_MODULE(OrderProcessing, CreateOrder); DBMS_APPLICATION_INFO.SET_ACTION(InsertOrder); END; / -- DBA根据模块名启用追踪 EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE( service_name ORCL, module_name OrderProcessing, action_name CreateOrder, waits TRUE, binds TRUE );四、Trace文件核心内容解读1. font color#1976D2Trace文件的三大部分/fontTrace文件结构 1. PARSING IN CURSOR部分SQL文本和执行统计 2. PARSE/EXEC/FETCH部分各阶段的详细时间和I/O 3. WAIT部分等待事件的详细记录2. font color#D32F2FPARSE/EXEC/FETCH关键指标/fontTrace文件示例PARSING IN CURSOR #140123456789 len45 dep0 uid101 ct3 tim1234567890123456 hv1234567890 SELECT * FROM emp WHERE emp_id :emp_id END OF STMT PARSE #140123456789:c1000,e1500,p0,cr5,cu0,mis1,r0,dep0,og1,tim1234567890123456 BINDS #140123456789: Bind#0 oacdty02 mxl22(22) mxlc00 mal00 scl00 pre00 value100 EXEC #140123456789:c0,e50,p0,cr0,cu0,mis0,r0,dep0,og1,tim1234567890123456 FETCH #140123456789:c5000,e5500,p2,cr100,cu0,mis0,r1,dep0,og1,tim1234567890123456关键字段解读| 字段 | 含义 | 说明 ||------|------|------||c| CPU时间微秒 | CPU消耗 ||e| Elapsed时间微秒 | 总耗时含等待 ||p| 物理读次数 | font color#D32F2F磁盘I/O次数/font ||cr| 一致性读逻辑读 | font color#F57C00逻辑读次数/font ||cu| 当前模式读 | DML操作的块读取 ||mis| 库缓存未命中 | font color#D32F2F1表示硬解析/font ||r| 返回行数 | 该阶段返回的行数 ||dep| 递归深度 | 0用户SQL0递归SQL |3. font color#F57C00等待事件解读/fontWAIT #140123456789: namdb file sequential read ela 5256 file#4 block#128 blocks1 obj#12345 tim1234567890123456 字段解读 nam 等待事件名称 ela 等待时间微秒 file# 数据文件编号 block# 数据块编号 obj# 对象ID五、TKPROF格式化工具详解1. font color#388E3CTKPROF基本用法/font# 基本格式化 tkprof tracefile.trc output.txt # 按Elapsed时间排序最常用 tkprof tracefile.trc output.txt sortexeela # 只显示Top 10 SQL tkprof tracefile.trc output.txt print10 # 聚合相同SQL tkprof tracefile.trc output.txt aggregateyes # 包含执行计划 tkprof tracefile.trc output.txt explainscott/tiger # 完整分析命令 tkprof tracefile.trc output.txt \ sortexeela \ print20 \ explainscott/tiger \ aggregateyesTKPROF排序选项| 排序键 | 含义 | 使用场景 ||--------|------|----------||exeela| 按执行Elapsed时间 | font color#388E3C最常用/font ||fchela| 按Fetch Elapsed时间 | 分析SELECT ||prsela| 按Parse Elapsed时间 | 分析硬解析 ||execpu| 按执行CPU时间 | CPU瓶颈 ||exedsk| 按执行物理读 | I/O瓶颈 ||exeqry| 按执行一致性读 | 逻辑读瓶颈 |2. font color#1976D2TKPROF报告解读/fontTKPROF输出示例SQL ID: a1b2c3d4 Plan Hash: 1234567890 SELECT * FROM emp WHERE emp_id :emp_id 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 2 0.00 0.00 2 100 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.00 0.00 2 100 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Rows Row Source Operation ------- --------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID EMP (cr100 pr2 pw0 time1500 us) 1 INDEX UNIQUE SCAN IDX_EMP_ID (cr2 pr0 pw0 time100 us)关键指标解读| 指标 | 含义 | 正常范围 ||------|------|----------||count| 执行次数 | - ||cpu| CPU时间秒 | - ||elapsed| 总耗时秒 | - ||disk| 物理读次数 | font color#388E3C越少越好/font ||query| 一致性读逻辑读 | font color#F57C00每个Fetch应100/font ||current| 当前模式读 | - ||rows| 返回行数 | - ||Misses in library cache| 硬解析次数 | font color#388E3C应该为0或1/font |六、实战诊断案例font color#D32F2F案例一逻辑读过高问题/fontTrace文件发现Fetch 10 2.50 3.00 0 5000000 0 10000诊断font color#D32F2F每个Fetch平均50万次逻辑读/font进一步分析SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(sql_id, NULL, ALLSTATS LAST)); -- 发现Full Table Scan on ORDERS优化创建索引CREATE INDEX idx_orders_date ON orders(order_date);优化后TraceFetch 5 0.10 0.12 2 5000 0 10000font color#388E3C逻辑读从500万降到5000降低了99.9%/fontfont color#1976D2案例二硬解析过多问题/fontTrace文件发现PARSE #1: mis1 ← 硬解析 PARSE #2: mis1 ← 又是硬解析 PARSE #3: mis1 ← 继续硬解析诊断font color#D32F2F未使用绑定变量。/font解决方案应用代码修改为绑定变量。七、总结记住这个“行车记录仪”类比就够了font color#1976D2【SQL Trace是行车记录仪AWR是交通流量报告】/fontAWR报告font color#1976D2交通流量报告——告诉你某条路平均车速慢。/fontSQL Tracefont color#D32F2F行车记录仪——精确记录每一秒的油门、刹车、等待。/font10046 Level 12font color#F57C00最高级别的记录仪记录速度变化车内录像GPS位置。/fontTKPROFfont color#388E3C视频分析软件——把行车录像变成可读的行驶报告。/fontfont color#1976D2SQL Trace是Oracle性能诊断中最底层、最精确的工具。当AWR报告无法定位问题时开启10046事件进行微观分析往往能发现问题的真正根因。/font你在日常工作中是否使用过SQL Trace诊断问题最常遇到的等待事件是什么欢迎评论区分享你的诊断经验。
SQL的显微镜：深度解析Oracle SQL Trace与TKPROF性能分析工具
一、开篇当AWR报告不够用时某天DBA通过AWR报告发现一条SQL消耗了大量资源但AWR报告只能看到汇总数据——这条SQL执行了1000次总耗时8000秒。font color#D32F2F但AWR无法告诉你这1000次执行中是每次都很慢还是个别几次慢时间花在解析上还是执行上是CPU等待还是I/O等待/fontfont color#1976D2这时候就需要SQL Trace出马。SQL Trace是Oracle最底层的SQL执行追踪工具可以记录SQL执行的每一个步骤——每次解析、每次I/O、每次等待事件精确到微秒级。/font本篇文章从10046事件启用、Trace文件解读、TKPROF格式化分析到实战诊断案例全面覆盖SQL Trace和TKPROF的使用技巧。二、SQL Trace架构全景图诊断应用格式化分析Trace文件生成追踪启用方式SQL Trace启用10046事件-当前会话DBMS_MONITOR-指定会话SQL Hint-MONITORuser_dump_dest目录V$SQL_MONITOR视图.trc原始Trace文件TKPROF格式化trcsess会话合并Trace Analyzer工具格式化报告.txtParse/Exec/Fetch耗时等待事件时间线逻辑读/物理读统计行源操作耗时关键解读font color#D32F2F红色10046事件/font 最常用的会话级追踪方式。font color#F57C00橘色Trace文件/font 原始追踪数据人类难以直接阅读。font color#388E3C绿色TKPROF/font 将Trace文件转换为可读的汇总报告。三、SQL Trace的启用方式1. font color#D32F2F10046事件最经典的追踪方式/font10046事件的级别| Level | 追踪内容 | 使用场景 ||-------|----------|----------|| 1 | 标准SQL Trace | 基本SQL执行信息 || 4 | Level 1 绑定变量值 | 需要查看绑定变量值 || 8 | Level 1 等待事件 | 需要分析等待事件 || 12 | Level 1 绑定变量 等待事件 | font color#388E3C最常用推荐级别/font |启用10046事件-- 对当前会话启用Level 12 ALTER SESSION SET EVENTS 10046 trace name context forever, level 12; -- 执行需要追踪的SQL SELECT * FROM orders WHERE order_id 100; -- 关闭10046事件 ALTER SESSION SET EVENTS 10046 trace name context off; -- 找到生成的Trace文件 SELECT value FROM v$diag_info WHERE name Default Trace File;2. font color#1976D2DBMS_MONITOR无需修改代码的追踪/font-- 获取目标会话的SID和SERIAL# SELECT sid, serial#, username, program FROM v$session WHERE username SCOTT; -- 启用追踪包含等待事件和绑定变量 EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE( session_id 123, serial_num 45678, waits TRUE, binds TRUE ); -- 关闭追踪 EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE( session_id 123, serial_num 45678 );3. font color#F57C00按服务/模块/操作追踪/font-- 应用代码中设置模块和操作 BEGIN DBMS_APPLICATION_INFO.SET_MODULE(OrderProcessing, CreateOrder); DBMS_APPLICATION_INFO.SET_ACTION(InsertOrder); END; / -- DBA根据模块名启用追踪 EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE( service_name ORCL, module_name OrderProcessing, action_name CreateOrder, waits TRUE, binds TRUE );四、Trace文件核心内容解读1. font color#1976D2Trace文件的三大部分/fontTrace文件结构 1. PARSING IN CURSOR部分SQL文本和执行统计 2. PARSE/EXEC/FETCH部分各阶段的详细时间和I/O 3. WAIT部分等待事件的详细记录2. font color#D32F2FPARSE/EXEC/FETCH关键指标/fontTrace文件示例PARSING IN CURSOR #140123456789 len45 dep0 uid101 ct3 tim1234567890123456 hv1234567890 SELECT * FROM emp WHERE emp_id :emp_id END OF STMT PARSE #140123456789:c1000,e1500,p0,cr5,cu0,mis1,r0,dep0,og1,tim1234567890123456 BINDS #140123456789: Bind#0 oacdty02 mxl22(22) mxlc00 mal00 scl00 pre00 value100 EXEC #140123456789:c0,e50,p0,cr0,cu0,mis0,r0,dep0,og1,tim1234567890123456 FETCH #140123456789:c5000,e5500,p2,cr100,cu0,mis0,r1,dep0,og1,tim1234567890123456关键字段解读| 字段 | 含义 | 说明 ||------|------|------||c| CPU时间微秒 | CPU消耗 ||e| Elapsed时间微秒 | 总耗时含等待 ||p| 物理读次数 | font color#D32F2F磁盘I/O次数/font ||cr| 一致性读逻辑读 | font color#F57C00逻辑读次数/font ||cu| 当前模式读 | DML操作的块读取 ||mis| 库缓存未命中 | font color#D32F2F1表示硬解析/font ||r| 返回行数 | 该阶段返回的行数 ||dep| 递归深度 | 0用户SQL0递归SQL |3. font color#F57C00等待事件解读/fontWAIT #140123456789: namdb file sequential read ela 5256 file#4 block#128 blocks1 obj#12345 tim1234567890123456 字段解读 nam 等待事件名称 ela 等待时间微秒 file# 数据文件编号 block# 数据块编号 obj# 对象ID五、TKPROF格式化工具详解1. font color#388E3CTKPROF基本用法/font# 基本格式化 tkprof tracefile.trc output.txt # 按Elapsed时间排序最常用 tkprof tracefile.trc output.txt sortexeela # 只显示Top 10 SQL tkprof tracefile.trc output.txt print10 # 聚合相同SQL tkprof tracefile.trc output.txt aggregateyes # 包含执行计划 tkprof tracefile.trc output.txt explainscott/tiger # 完整分析命令 tkprof tracefile.trc output.txt \ sortexeela \ print20 \ explainscott/tiger \ aggregateyesTKPROF排序选项| 排序键 | 含义 | 使用场景 ||--------|------|----------||exeela| 按执行Elapsed时间 | font color#388E3C最常用/font ||fchela| 按Fetch Elapsed时间 | 分析SELECT ||prsela| 按Parse Elapsed时间 | 分析硬解析 ||execpu| 按执行CPU时间 | CPU瓶颈 ||exedsk| 按执行物理读 | I/O瓶颈 ||exeqry| 按执行一致性读 | 逻辑读瓶颈 |2. font color#1976D2TKPROF报告解读/fontTKPROF输出示例SQL ID: a1b2c3d4 Plan Hash: 1234567890 SELECT * FROM emp WHERE emp_id :emp_id 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 2 0.00 0.00 2 100 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.00 0.00 2 100 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Rows Row Source Operation ------- --------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID EMP (cr100 pr2 pw0 time1500 us) 1 INDEX UNIQUE SCAN IDX_EMP_ID (cr2 pr0 pw0 time100 us)关键指标解读| 指标 | 含义 | 正常范围 ||------|------|----------||count| 执行次数 | - ||cpu| CPU时间秒 | - ||elapsed| 总耗时秒 | - ||disk| 物理读次数 | font color#388E3C越少越好/font ||query| 一致性读逻辑读 | font color#F57C00每个Fetch应100/font ||current| 当前模式读 | - ||rows| 返回行数 | - ||Misses in library cache| 硬解析次数 | font color#388E3C应该为0或1/font |六、实战诊断案例font color#D32F2F案例一逻辑读过高问题/fontTrace文件发现Fetch 10 2.50 3.00 0 5000000 0 10000诊断font color#D32F2F每个Fetch平均50万次逻辑读/font进一步分析SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(sql_id, NULL, ALLSTATS LAST)); -- 发现Full Table Scan on ORDERS优化创建索引CREATE INDEX idx_orders_date ON orders(order_date);优化后TraceFetch 5 0.10 0.12 2 5000 0 10000font color#388E3C逻辑读从500万降到5000降低了99.9%/fontfont color#1976D2案例二硬解析过多问题/fontTrace文件发现PARSE #1: mis1 ← 硬解析 PARSE #2: mis1 ← 又是硬解析 PARSE #3: mis1 ← 继续硬解析诊断font color#D32F2F未使用绑定变量。/font解决方案应用代码修改为绑定变量。七、总结记住这个“行车记录仪”类比就够了font color#1976D2【SQL Trace是行车记录仪AWR是交通流量报告】/fontAWR报告font color#1976D2交通流量报告——告诉你某条路平均车速慢。/fontSQL Tracefont color#D32F2F行车记录仪——精确记录每一秒的油门、刹车、等待。/font10046 Level 12font color#F57C00最高级别的记录仪记录速度变化车内录像GPS位置。/fontTKPROFfont color#388E3C视频分析软件——把行车录像变成可读的行驶报告。/fontfont color#1976D2SQL Trace是Oracle性能诊断中最底层、最精确的工具。当AWR报告无法定位问题时开启10046事件进行微观分析往往能发现问题的真正根因。/font你在日常工作中是否使用过SQL Trace诊断问题最常遇到的等待事件是什么欢迎评论区分享你的诊断经验。
