Oracle中如何获取函数中正在执行的真实SQL语句(定位存储过程中最耗时部分)

最近遇到开发反馈一个执行将近2天的存储过程，需要分析慢的原因，汇总记录一下。

通过v$session视图

v$session中的sql_id是一直变化的，所以就是存储过程中当前正在执行的真实SQL：

ash视图

如果v$ash视图中还有数据，尽量用这个，没有的话用dba_hist_ash

原理就是ash视图有top_level_sql_id（存储过程对应的sql_id），每个sql又有sql_exec_start，可以根据执行时间定位sql_id执行时间和次数。

再根据临时表 proc_run_time 做分析统计

缺点：

• 当然这个统计结果没有dbms_profiler准确，但大致能看出来，并且不需要再次运行存储过程。
• 如果是嵌套多层的存储过程，可能需要循环多次执行上面步骤
• 需要自己写SQL分析，不够方便

10046 trace

可以通过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配置对话框

这样 就可以对存储过程做一个很好的分析，从而对其进行优化。

存储过程中加入计时代码

原始的分析方法，适用于较简单、性能要求不太高的存储过程场景。在怀疑段设置计时点，不断缩小范围。

缺点：

• 需要改业务代码
• 复杂存储过程需要多次或者大量设置，可行性不高
• 需要再次执行存储过程
• 计时点设置过多可能影响存储过程本身性能

dbms_profiler

用于分析Oracle存储过程中的各段代码的时间开销情况，从而快速找到性能瓶颈的步骤。dbms_profiler，专门用于分析Oracle存储过程中的各段代码的时间开销情况，从而快速找到性能瓶颈的步骤。

1、 sys创建dbms_profiler

主要函数:

• start_profiler 启动对该程式监控

• stop_profiler 结束对该程式监控

  2、 创建profiler用户和对象

  conn / as sysdba; CREATE USER profiler IDENTIFIED BY profiler; grant connect,resource to profiler; conn profiler/profiler; @?/rdbms/admin/proftab.sql GRANT SELECT ON plsql_profiler_runnumber TO PUBLIC; GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_data TO PUBLIC; GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_units TO PUBLIC; GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_runs TO PUBLIC; -- 建同义词 CREATE PUBLIC SYNONYM plsql_profiler_runnumber FOR profiler.plsql_profiler_runnumber; CREATE PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs; CREATE PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units; CREATE PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;

  1 2 3 4 5 6 7 8 9 10 11 12 13 14

  conn / as sysdba; CREATE USER profiler IDENTIFIED BY profiler; grant connect,resource to profiler; conn profiler/profiler; @?/rdbms/admin/proftab.sql GRANT SELECT ON plsql_profiler_runnumber TO PUBLIC; GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_data TO PUBLIC; GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_units TO PUBLIC; GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_runs TO PUBLIC; -- 建同义词 CREATE PUBLIC SYNONYM plsql_profiler_runnumber FOR profiler.plsql_profiler_runnumber; CREATE PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs; CREATE PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units; CREATE PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;

  备注：

• plsql_profiler_runs：prof运行信息

• plsql_profiler_units：prof每个单元信息

• plsql_profiler_data：prof每个单元的详细数据

• plsql_profiler_runnumber：用来生成prof唯一运行编号的序列

  3、 使用dbms_profiler收集信息

  假设要对下面这样的一个存储过程进行分析

  CREATE OR REPLACE procedure sp_profiler_test1 as begin for x in 1..10000 loop insert into t_t1 values(x); end loop; commit; end sp_profiler_test1; /

  1 2 3 4 5 6 7 8 9 10

  CREATE OR REPLACE procedure sp_profiler_test1 as begin for x in 1..10000 loop    insert into t_t1 values(x); end loop; commit; end sp_profiler_test1; /

  收集该存储过程执行信息方法如下：

  set serverout on; DECLARE v_run_number integer; v_temp1 integer; BEGIN -- 启动profiler sys.DBMS_PROFILER.start_profiler (run_number => v_run_number); -- 显示当前跟踪的运行序号(后面查询要用) DB MS_OUTPUT.put_line ('run_number:' || v_run_number); -- 运行要跟踪的PLSQL sp_profiler_test1; --前一步创建的测试样例存储过程 -- 停止profiler sys.DBMS_PROFILER.stop_profiler; END;

  1 2 3 4 5 6 7 8 9 10 11 12 13 14

  set serverout on; DECLARE v_run_number   integer; v_temp1        integer; BEGIN -- 启动profiler sys.DBMS_PROFILER.start_profiler (run_number => v_run_number); -- 显示当前跟踪的运行序号(后面查询要用) DB MS_OUTPUT.put_line ('run_number:' || v_run_number); -- 运行要跟踪的PLSQL sp_profiler_test1;   --前一步创建的测试样例存储过程 -- 停止profiler sys.DBMS_PROFILER.stop_profiler; END;

  4、 查询并分析结果

  set linesize 1000 col text format a60 SELECT d.line#, -- 代码行号 s.text, -- 源代码 d.total_time, -- 总共运行时间(单位10亿分之一秒，即10的-9次方。） d.total_occur, -- 总共运行次数 d.min_time, -- 最小运行时间 d.max_time -- 最大运行时间 FROM plsql_profiler_data d, sys.all_source s, plsql_profiler_units u WHERE d.runid = 2 -- 运行号（上一步执行相关过程时显示号码） and u.unit_name = 'SP_PROFILER_TEST1' -- 单元名，即被测试的存储过程名 AND u.runid = d.runid AND d.unit_number = u.unit_number AND d.total_occur <> 0 AND s.TYPE(+) = u.unit_type AND s.owner(+) = u.unit_owner AND s.name(+) = u.unit_name AND d.line# = NVL (s.line, d.line#) ORDER BY d.total_time desc, u.unit_number, d.line#;

  1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

  set linesize 1000 col text format a60 SELECT   d.line#,                      -- 代码行号 s.text,                            -- 源代码    d.total_time,                   -- 总共运行时间(单位10亿分之一秒，即10的-9次方。）    d.total_occur,                  -- 总共运行次数    d.min_time,                     -- 最小运行时间    d.max_time                      -- 最大运行时间 FROM   plsql_profiler_data d, sys.all_source s, plsql_profiler_units u WHERE       d.runid = 2             -- 运行号（上一步执行相关过程时显示号码） and u.unit_name = 'SP_PROFILER_TEST1'        -- 单元名，即被测试的存储过程名    AND u.runid = d.runid AND d.unit_number = u.unit_number AND d.total_occur <> 0 AND s.TYPE(+) = u.unit_type AND s.owner(+) = u.unit_owner AND s.name(+) = u.unit_name AND d.line# = NVL (s.line, d.line#) ORDER BY  d.total_time desc, u.unit_number, d.line#;

  示例查询结果如下：

  LINE# TEXT TOTAL_TIME TOTAL_OCCUR MIN_TIME MAX_TIME ---------- -------------------------------------- ---------- ----------- ---------- ---------- 6 insert into t_t1 values(x); 150147563 10000 13108 3831882 4 for x in 1..10000 613220 10001 26 7514 8 commit; 75630 1 75630 75630 9 end sp_profiler_test1; 1683 1 1683 1683 Elapsed: 00:00:01.39

  1 2 3 4 5 6 7

  LINE# TEXT                                   TOTAL_TIME TOTAL_OCCUR   MIN_TIME   MAX_TIME ---------- -------------------------------------- ---------- ----------- ---------- ----------      6        insert into t_t1 values(x);      150147563       10000      13108    3831882      4    for x in 1..10000                       613220       10001         26       7514      8    commit;                                  75630           1      75630      75630      9 end sp_profiler_test1;                       1683           1       1683       1683 Elapsed: 00:00:01.39

• LINE#：对应TEXT的语句在存储过程的第几行

• TOTAL_TIME：执行的总时间（单位ns）

• TOTAL_OCCUR：执行的次数

• MIN_TIME：最短单次的运行时间（单位ns）

• MAX_TIME：最长单次的运行时间（单位ns）

  另附几个plsql相关sql
  查询plsql执行时间占整个数据库执行时间比重

  col db_time_secs format 999,999,999.99 col plsql_time_secs format 999,999,999.99 col pct_plsql_time format 99.99 col execs heading "Execs" col text heading "Line text" set lines 100 set pages 10000 set echo on WITH plsql_times AS (SELECT SUM (CASE stat_name WHEN 'DB time' THEN value/1000000 END) AS db_time, SUM(CASE stat_name WHEN 'PL/SQL execution elapsed time' THEN value / 1000000 END) AS plsql_time FROM v$sys_time_model WHERE stat_name IN ('DB time', 'PL/SQL execution elapsed time')) SELECT ROUND (db_time, 2) db_time_secs, ROUND (plsql_time, 2) plsql_time_secs, ROUND (plsql_time * 100 / db_time, 2) pct_plsql_time FROM plsql_times

  1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22

  col db_time_secs format 999,999,999.99 col plsql_time_secs format 999,999,999.99 col pct_plsql_time format 99.99 col execs heading "Execs" col text heading "Line text" set lines 100 set pages 10000 set echo on WITH plsql_times    AS (SELECT SUM (CASE stat_name                         WHEN 'DB time'                         THEN value/1000000 END) AS db_time,               SUM(CASE stat_name                        WHEN 'PL/SQL execution elapsed time'                        THEN value / 1000000 END) AS plsql_time          FROM v$sys_time_model         WHERE stat_name IN ('DB time',                          'PL/SQL execution elapsed time')) SELECT ROUND (db_time, 2) db_time_secs,    ROUND (plsql_time, 2) plsql_time_secs,    ROUND (plsql_time * 100 / db_time, 2) pct_plsql_time FROM plsql_times

  通过v$sql获取所用时间详细数字，包含plsql执行时间、plsql占总sql执行时间比例、语句占数据库中所有plsql开销比例

  set lines 100 set pages 1000 col sql_text format a30 heading "SQL Text" col elapsed_ms format 9999999 heading "Total|time ms" col plsql_ms format 99999999 heading "PLSQL|time ms" col pct_plsql format 99.99 heading "Pct|PLSQL" col pct_total_plsql format 99.99 heading "PCT of|Tot PLSQL" set echo on SELECT sql_id, SUBSTR (sql_text, 1, 150) AS sql_text, ROUND (elapsed_time / 1000) AS elapsed_ms, ROUND (plsql_exec_time / 1000) plsql_ms, ROUND (plsql_exec_time * 100 / elapsed_time, 2) pct_plsql, ROUND (plsql_exec_time * 100 / SUM (plsql_exec_time) OVER (), 2) pct_total_plsql FROM v$sql WHERE plsql_exec_time > 0 AND elapsed_time > 0 ORDER BY plsql_exec_time DESC

  1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18

  set lines 100 set pages 1000 col sql_text format a30 heading "SQL Text" col elapsed_ms format 9999999 heading "Total|time ms" col plsql_ms format 99999999 heading "PLSQL|time ms" col pct_plsql format 99.99 heading "Pct|PLSQL" col pct_total_plsql format 99.99 heading "PCT of|Tot PLSQL" set echo on SELECT sql_id,    SUBSTR (sql_text, 1, 150) AS sql_text,    ROUND (elapsed_time / 1000) AS elapsed_ms,    ROUND (plsql_exec_time / 1000) plsql_ms,    ROUND (plsql_exec_time * 100 / elapsed_time, 2) pct_plsql,    ROUND (plsql_exec_time * 100 / SUM (plsql_exec_time) OVER (), 2)       pct_total_plsql FROM v$sql WHERE plsql_exec_time > 0 AND elapsed_time > 0 ORDER BY plsql_exec_time DESC

缺点：

需要创建提前额外profiler用户和对象
存储过程执行前要运行dbms_profiler相关代码，只适合手动执行存储过程时分析
需要再次执行存储过程

AWR

如果在存储过程执行期间别的SQL运行不多，很可能存储过程和其中最慢的具体sql都会在top 榜单上。根据sql module字段可以方便定位和优化。

参考

https://blog.csdn.net/Hehuyi_In/article/details/121752914

https://blog.csdn.net/Hehuyi_In/article/details/107771428