简单几招捕获Oracle递归SQL调用源头

蒋健 2016-11-28 10:01:43

作者介绍

蒋健，云趣网络科技联合创始人，11g OCM，多年Oracle设计、管理及实施经验，精通数据库优化，Oracle CBO及并行原理，曾为多个行业的客户的 Oracle 系统实施小型机到 X86跨平台迁移和数据库优化服务。云趣鹰眼监控核心设计和开发者，资深Python Web开发者。

一、概述

通常，DBA 确定通过 Oracle 的顶级活动会话图确定 Top SQL，有了 SQL 的执行会话信息和 SQL 文本，可以和开发人员确定 Top SQL 来自哪些应用模块的。有时候，Oracle DBA 需要自己确认 SQL 的来源，本文将演示如何使用 Oracle 提供丰富的跟踪功能，来确认递归 SQL 的调用者来源。

二、问题描述

通过顶级会话页面，DBA 发现一个异常的 Top SQL，SQL ID 为c7452agj0s0t6，消耗了9%的数据库时间。

通过 SQL 详情页面，可以确定 SQL c7452agj0s0t6 的用户名和模块，但是没有确定 SQL c7452agj0s0t6 是哪个客户机器造成的。

从 SQL 的文本中，这是一个针对系统视图 V$ACTIVE_SESSION_HISTORY 的查询。

SELECT GROUP_TYPE, BUCKET_START, BUCKET_END, TM_GROUP_TYPE, TM_BUCKET_START,

TM_BUCKET_END, SUM(TM_CPU_FIRST_BUCKET_VALUE) TM_CPU_FIRST_BUCKET_VALUE,

SUM(TM_CPU_MIDDLE_BUCKETS_VALUE) TM_CPU_MIDDLE_BUCKETS_VALUE,

... 省略大量 SQL 文本

FROM TABLE(SYS.GV$(CURSOR(

... 省略大量 SQL 文本

SELECT ASH0.*

FROM V$ACTIVE_SESSION_HISTORY ASH0

... 省略大量 SQL 文本

通过 SQL 的活动会话信息，可以确定执行该 SQL 的进程为后台 PZ 进程，这些会话的 QC（query coordinator）不为空，也就是这是针对视图 V$ACTIVE_SESSION_HISTORY 的并行查询造成的。因为执行时间很短，并且执行此 SQL 的会话为短连接，无法查询到 QC 会话的来源。

三、SQL ID 级别的跟踪分析

为了确定 SQL c7452agj0s0t6 的来源，我们使用 Oracle 11g 中的新功能，对单个 SQL ID 打开10046事件跟踪，命令如下：

alter system set events 'sql_trace [sql:c7452agj0s0t6] wait=true,bind=true,plan_stat=all_executions,level=12';

通过以下查询确定 trace 文件的产生目录：

select value from v$diag_info where name='Default Trace File';

对最新生成的 PRDDB_oraxxx.trc 执行 grep c7452agj0s0t6，找到跟踪文件如下，可以确定该的客户端为 testapp。通过 dep=2，知道 SQL c7452agj0s0t6 为深度二级的递归 SQL，并不是用户直接提交的 SQL。我们依然不知道这个递归 SQL 具体由什么 SQL 调用的。

*** 2016-10-14 09:34:13.921

*** SESSION ID:(329.41269) 2016-10-14 09:34:13.921

*** CLIENT ID:() 2016-10-14 09:34:13.921

*** SERVICE NAME:(PRDDB) 2016-10-14 09:34:13.921

*** MODULE NAME:(python@testapp (TNS V1-V3)) 2016-10-14 09:34:13.921

*** ACTION NAME:() 2016-10-14 09:34:13.921

... 省略大量文本

=====================

PARSING IN CURSOR #139987897061528 len=11079 dep=2 uid=87 oct=3 lid=87 tim=1476408854404253 hv=3792438054 ad='21b01ba960' sqlid='c7452agj0s0t6'

关闭 SQL ID 跟踪的命令如下：

alter system set events 'sql_trace [sql:c7452agj0s0t6] off';

四、会话级别的跟踪分析

为了确认什么 SQL 调用了 c7452agj0s0t6，我们需要在会话级别打开10046跟踪，因为执行 SQL c7452agj0s0t6 的会话是短连接，我们创建一个针对用户 APPUSER 的 logon 触发器，下次这个用户登录时会启动10046跟踪。

create or replace trigger sys.set_trace

after logon on database

when (user in ('APPUSER')）

declare

begin

execute immediate 'alter session set statistics_level=all';

execute immediate 'alter session set max_dump_file_size=unlimited';

execute immediate 'alter session set events ''10046 trace name context forever, level 12''';

end set_trace;

接着，在跟踪文件目录中找到最新生成的跟踪文件 PRDDB1_ora_10452.trc 包含 SQL ID c7452agj0s0t6。接着我们使用 orasrp 这个工具分析10046跟踪文件. orasrp 为 Oracle Session Resource Profiler，出自一位俄罗斯 DBA 的强大的10046分析工具，网址为：http://oracledba.ru/orasrp/

orasrp PRDDB1_ora_10452.trc PRDDB1_ora_10452.html

orasrp相对于 Oracle 自带的 tkprof，功能更加强大，其中一大优势是会生成会话的递归调用树。递归调用树(Session Call Graph)部分如下图，SQL hash value=3792438054 为 SQL c7452agj0s0t6，深度为2，顶级的 SQL hash value = 2036392974。

顶级 SQL 文本如下，原来 SQL c7452agj0s0t6 是由 dbms_sqltune.report_sql_monitor 这个生成 SQL Monitor 报告的函数递归调用的。确定是前几天新部署的监控 job，在后台定时抓取和保存新生成的 SQL monitor 报告，但是执行过于频繁。解决的方法为降低后台 job 的执行频率，对每次抓取 SQL monitor 的执行时间提高限制。

select dbms_sqltune.report_sql_monitor(type=>:1, sql_id=>:2, sql_exec_id=>:3, report_level=>'ALL') monitor_report from dual;

确定问题来源之后，删除 logon 触发器，避免过多的跟踪文件产生：

drop trigger sys.set_trace;

五、总结

本文演示了如果在 Oracle 中分别使用 SQL ID 和会话级别的10046跟踪，以确定递归 SQL 的调用源头来自 PL/SQL 函数 dbms_sqltune.report_sql_monitor。现实工作中，使用类似的方法，可以对 PL/SQL 代码性能，Oracle 解析时间过长等疑难杂症进行分析。对于 DBA 来说，使用 orasrp 对10046跟踪文件生成的递归调用树，也是研究应用负载特征的一个好手段。