合 Oracle中如何获取函数中正在执行的真实SQL语句(定位存储过程中最耗时部分)
最近遇到开发反馈一个执行将近2天的存储过程，需要分析慢的原因，汇总记录一下。
通过v$session视图
v$session中的sql_id是一直变化的，所以就是存储过程中当前正在执行的真实SQL：
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 | select a.LAST_CALL_ET,a.sid,a.status,a.sql_id,a.USERNAME,a.EVENT from v$session a where a.username is not null and a.PROGRAM='sqlplus.exe'; select a.LAST_CALL_ET,a.sid,a.status,a.sql_id,a.USERNAME,a.EVENT from v$session a where a.SQL_ID='3vn4sbyvsd08y'; select * from v$sql_monitor d where d.status not like 'DONE%'; SELECT dbms_sqltune.report_sql_monitor(sql_id => '99qfh6psd3cpy',type => 'html',report_level => 'all') FROM dual; -- 慢SQL SELECT a.USERNAME, (SELECT upper(nb.OSUSER) FROM v$session nb WHERE nb.SID = a.sid) OSUSER, (SELECT nb.sid || ',' || nb.SERIAL# || ',' || pr.SPID FROM v$process pr, v$session nb WHERE nb.PADDR = pr.ADDR and nb.sid = a.SID and nb.SERIAL# = a.SERIAL#) session_info, a.opname, to_char(a.START_TIME, 'YYYY-MM-DD HH24:MI:SS') start_time, round(a.SOFAR * 100 / a.TOTALWORK, 2) || '%' AS progress, a.TIME_REMAINING TIME_REMAINING, a.elapsed_seconds elapsed_seconds, message message, (SELECT nb.EVENT FROM V$session_Wait nb WHERE nb.SID = a.SID) wait_event, (SELECT nb.STATUS FROM v$session nb WHERE nb.SID = a.SID) STATUS FROM v$session_longops a WHERE a.time_remaining <> 0 ORDER BY status, a.TIME_REMAINING DESC, a.SQL_ID, a.sid; |
ash视图
如果v$ash视图中还有数据，尽量用这个，没有的话用dba_hist_ash
原理就是ash视图有top_level_sql_id（存储过程对应的sql_id），每个sql又有sql_exec_start，可以根据执行时间定位sql_id执行时间和次数。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 | create table proc_run_time as SELECT T.SQL_ID, T.SQL_EXEC_ID, CAST(MAX(T.SAMPLE_TIME) AS DATE) EXEC_END_TIME, T.SQL_EXEC_START EXEC_START_TIME, ROUND((CAST(MAX(T.SAMPLE_TIME) AS DATE) - T.SQL_EXEC_START) * 1440 * 60, 2) RUN_S, T.SQL_PLAN_HASH_VALUE, T.MODULE FROM v$active_session_history T WHERE T.top_level_sql_id = 'fvtrazmp924f7' --------- 注意这里 AND T.SAMPLE_TIME > SYSDATE - 2 GROUP BY T.SQL_ID, T.SQL_EXEC_ID, T.SQL_EXEC_START, T.SQL_PLAN_HASH_VALUE, T.MODULE ORDER BY EXEC_END_TIME DESC |
再根据临时表 proc_run_time 做分析统计
1 2 3 4 5 | select sql_id,count(*) execution,sum(run_s) elapsed_time_s from proc_run_time where run_s is not null and exec_start_time >= to_date('2021-11-30 20:00','yyyy-mm-dd hh24:mi') group by sql_id order by 3 desc |
缺点：
- 当然这个统计结果没有dbms_profiler准确，但大致能看出来，并且不需要再次运行存储过程。
- 如果是嵌套多层的存储过程，可能需要循环多次执行上面步骤
- 需要自己写SQL分析，不够方便
10046 trace
1 2 3 4 | SQL>execute sys.dbms_system.set_ev(7,36,10046,12,''); exec sql SQL>execute sys.dbms_system.set_ev(7,36,10046,0,''); tkprof ora_2229_10046.trc 888.trc |
可以通过disk 排序之类的方式，定位TOP SQL
缺点：
- 需要再次执行一次存储过程；
- 不高效，需要对disk 操作系统文件进行一定的grep 过滤 order by 人为查询
plsqldev工具
可以进行debug进行调试，或者进行如下的分析：
首先创建dbms_profiler包，而且还要创建一个用于存放跟踪信息的用户，及其prof表和序列的同义词，最后用profiler用户创建prof表和序列，并赋权。
下面将详细介绍在PLSQL DEVELOPER 应用Profiler：
1、右键存储过程，单击测试
2、单击测试后，会弹出一个测试窗口，如下图，此时点击"创建概览图报告"
3、点击"执行" 或者 F8 执行存储过程
4、执行完后 点击"测试窗口" 上的 概览图 会出现如下：
每列的详细意义如下：
unit --单元名称，即执行的存储过程，包括其调用的过程
line --代码行号
total time --此行执行时间(颜色长度表示本行代码的执行时间与最长代码执行时间的百分比图)
occurrences --此行执行次数
text --对应代码行，对于加密的代码，将不能显示
Average time —平均运行时间
maximum time --最大运行时间
minimum time --最小运行时间（以上三个时间默认不显示，可以通过配置对话框选择显示，参加4.4）
列表中显示的源代码只显示一行，如果要定位则可以在对应的行中打开右键，选择[Go to unit line] ，这样就会直接跳到对应的源代码位置。
Profiler面板的工具栏说明：
a、显示配置对话框
b、刷新
c、删除当前运行号的数据
d、Run 显示当前的系统的所有Profiler列表，缺省为当前的跟踪
e、Unit 显示本次跟踪的单元列表信息（执行时间），缺省为所有单元的执行时间
5.4、Profiler配置对话框
这样 就可以对存储过程做一个很好的分析，从而对其进行优化。
