ASH查不到存储过程内循环或赋值耗时,因其仅采样发出SQL或产生等待的活跃会话,纯PL/SQL运算(如循环、字符串拼接)不触发可观测动作,sql_id为NULL且无对应行级信息;DBMS_PROFILER是唯一支持PL/SQL行级耗时的官方工具,需提前部署、显式启停并确保数据完整性。
ash 本身不记录存储过程内部的“每一步”,只记录它发出的 sql 和等待事件;想看 pl/sql 层级的逐行耗时,必须用 dbms_profiler 或手动插点计时,不能靠 ash。
为什么 ASH 查不到存储过程里的循环或赋值耗时?
ASH 的采样对象是“活动会话”——即正在执行 SQL、等待 I/O 或处于 ON CPU 状态且已发出底层操作的会话。纯 PL/SQL 运算(比如 FOR i IN 1..100000 LOOP ... END LOOP、字符串拼接、JSON 解析)不触发 SQL 执行也不进入等待队列时,sql_id 为 NULL,session_state 可能是 ON CPU,但 plsql_entry_object_id 虽有效,却无法关联到具体哪一行代码。
- 常见表现:查到
plsql_entry_object_id = 12345的样本,sql_id IS NULL,event为空,program_id/program_line#在v$sql中查不到对应记录 - 本质限制:ASH 不解析 PL/SQL 字节码,不挂钩 PL/SQL 引擎的执行步进器
- 别误以为“没采到 = 没执行”,更可能是“执行了但没对外发任何可观测动作”
怎么用 DBMS_PROFILER 真正拿到每行耗时?
DBMS_PROFILER 是 Oracle 唯一能落到 PL/SQL 行级的官方工具,但它需要提前部署、显式启停,且结果依赖 plsql_profiler_data 表的完整性。
- 必须先运行
@?/rdbms/admin/proftab.sql创建 profiler 表结构(通常由 DBA 在profiler用户下完成) - 调用前必须
DBMS_PROFILER.START_PROFILER,结束后必须DBMS_PROFILER.STOP_PROFILER,中间任意异常未 stop 都会导致数据残缺 - 关键字段不是
total_time(单位是纳秒但含误差),而是total_occur和min_time/max_time的组合——单次执行中某行被命中多少次、最短/最长耗时,比平均值更有诊断价值 - 如果存储过程带
OUT参数且被匿名块调用,profiler 仍能捕获,但需确保调用者会话有 profiler 权限,且run_comment唯一以便后续过滤
DBMS_UTILITY.GET_TIME 插桩要注意什么?
这是最轻量、最可控的手动计时方式,但极易因漏写或换算错误导致数据失真。
-
DBMS_UTILITY.GET_TIME返回的是厘秒(1/100 秒),不是毫秒,差值必须除以100才是秒:(end_time - start_time) / 100 - 不能复用同一组
start_time/end_time变量——嵌套逻辑或异常分支会覆盖变量值,应为每段独立声明:step1_start NUMBER; step1_end NUMBER; -
EXCEPTION块里必须补一次stepX_end := DBMS_UTILITY.GET_TIME,否则该段耗时永远为 0 或报ORA-06502 - 避免在
END处统一收口:PL/SQL 遇到异常直接跳出,END根本不执行
真正难的不是选哪个工具,而是接受一个事实:ASH 只告诉你“过程在跑”,DBMS_PROFILER 告诉你“哪行慢”,而 DBMS_UTILITY.GET_TIME 告诉你“这段花了多久”——三者定位层级不同,混用时要清楚各自边界。尤其注意 plsql_entry_object_id 在 ASH 中只在“过程刚被调用且尚未退出”的窗口内有效,过了这个窗口就再也捞不回来。


















