通过trace分析定位ORACLE统计信息收集带来的问题-技术人生系列第二十二期

来源:这里教程网 时间:2026-03-03 12:38:15 作者:

前言:

对于 DBA 来说,掌握数据库的各种特性是保证数据库性能稳定的重要前提之一;统计信息的准确性通常是我们日常运维的难题之一,如何保证统计信息的及时更新有效,而在此过程中是否会引起其他的问题?今天的分享给大家带来的 CASE 将展示此中隐患,同时通过 CASE 我们来看看我们如何使用 trace 文件的分析快速定位问题,并最终给出日常运维的几条建议。

不一样的任务

对于长期处于一线的 DBA 来说,处理性能故障的最好方式当然是登录到目标服务器,以飞快的手速查询各种性能视图,收集各种信息,然后再综合判断解决问题;然而,对于一些数据中心来说,如果作为远程支持,可能直接登录目标服务器就是一种奢望了,更多的是依赖客户能及时提供我们所想看到的信息来快速判断问题所在;

话说一天下午,某客户打电话要求远程支持,他们遇到的情况是这样的:

前一天,某系统在中午 12 点到 1 点前后出现过有几段时间数据库响应缓慢的情况,最后客户自己在简单判断之后通过重启应用解决了该问题,然后已经将帮助处理问题的 重要信息 发送到邮箱,需要我们帮忙协助核查为何会出现这样的情况,如何避免该情况再次发生。

客户的要求

对于我们日常运维而言,如果系统出现了短时夯或者响应缓慢,通常我们的第一要务是恢复业务,然而,为了能防止问题再次发生,我们需要存留相关信息来分析问题根因,那么在恢复业务前,如果可能,我们尽可能做到以下:

1)     通过建表的方式保留问题时段的 gv$active_session_history 信息

2)     在问题时段内做多次 snapshot 确保能生成一个全程为故障时间的 AWR 报告

3)     如果系统夯,收集 systemstatedump/hanganalyze 数据

4)     如果有可能,收集相关进程的 processdump

5)     保留问题时段 oracle 后台产生的各种 trace/dump 文件

客户这一次给过来的“重要文件”似乎只有 background_dump_dest 目录下的 alert 日志和 trace 文件,这对性能分析来说似乎是不够的,然而,再联系客户,客户自己还需要忙别的工作,同时, 登录服务器取更多的信息发送过来在流程上也是一件非常麻烦的事,客户要求我们可以先通过已有的信息来分析 ,如果没有结论,可以随后一天到现场进行跟进。

trace 是个好东西

简单翻看了 alert 日志,并没有什么特别的信息,不过,很幸运,数据库出现问题的时间段, oracle dia0 进程在判断系统出现性能存在问题时,产生了大量的 dia0 trace 文件,这些文件相当于在问题时刻对数据库做了一个 hanganalyze 操作,完全可以帮助我们初步定位问题的方向;看起来,虽然只有一些 trace 文件,但是只要有足够耐心,还是多少能从中找到一些端倪的, trace 也是个好东西。

解读 trace 一点也不难

在数据库性能缓慢的时间段内, dia0 进程产生了多个不同的 trace 文件,我们可以通过不同时间点的 hang 分析来定位数据库的性能问题原因;我们先选取其中一个 trace 文件进行分析;

可以看到,这是 dia0 进程 109811 产生的一个 trace 文件,产生的时间点为问题时段的 02-20 13:19 左右;

具体分析,可以先大概了解到 hang 的过程中受影响的操作是解析,最新的夯的等待事件是 library cache lock

  接下来,简单看单个 wait chain 的详细情况如下:

可以简单看到 chain 1 的阻塞者和被阻塞者的等待事件,最终简单的体现在 Chain 1 Signature 记录上;这样,我们通过关键字 Signature 来搜索显示整个 trace 文件中等待关系如下:

这里居然有 170 条等待链,而且从 Signature 中看,也基本没有出现多个等待链合并到其中某个等待链的情况;那么,这么多等待链,接下来我们需要怎样继续分析呢?亲爱的读者,不如停下来想想,这个时候需要些什么知识来帮助我们继续分析下去呢?如果是你,你会怎样继续呢?

~

~

~

~

熟悉的等待事件和等待关系

其实通过上述信息我们大致已经知道,数据库中问题时段的主要等待事件就是 ’cursor: pin S wait on X’ ‘library cache lock’ ;有经验的读者朋友一定对这两个等待事件都并不陌生,而且在技术人生系列的之前的分享中,这两个等待事件也有专门介绍过,这里不妨我们再简单介绍一下两个等待事件:

‘cursorpin S wait on X’ 一般出现在解析 / 编译时,当一个会话正在对某语句 / 某存储过程进行解析 / 编译时,会在对应的 cursor 上持有 X 模式的 pin ,而当有其他会话想要读取该 cursor 时,会请求 S 模式的 pin ,这时这些想读取 cursor 的会话将会出现 ’cursor:pin S wait on X’ 等待事件;其中 p1 标识涉及的 cursor

‘librarycache lock’ 一般出现在涉及 share pool 中对象被修改时产生的竞争,涉及的对象包括表 / 索引 / 数据包等;其中 p1 标识竞争的对象句柄地址 (handle address)

 

当我们看到 Signature: 'library cachelock'<='cursor: pin S wait on X'   时不应该感到奇怪,出现这种情况通常可以理解为,当一个会话 1 解析某 SQL/ 编译某 procedure 等时,它因为某些原因在等待 ’library cache lock’ 等待事件,而随后另一个会话 2 也需要执行同样的 sql/procedure ,因为会话 1 还正在解析,会话 2   即产生了 ’cursor:pin S wait on X’ 等待事件;  

chain1 为例,可以看到 1 节点的会话 784 正在请求 12351d63 16 进制)的 S 模式的 pin ,而此时该 pin X 模式持有者会话 628 则在解析 / 编译阶段出现了 library cache lock 等待,无法及时请求到 7a6f8c530 句柄上的 library cache lock

同样,当我们看到 Signature: 'library cache lock' 时就更简单了,只是某个会话正在解析时请求 librarycache lock ,而区别只是数据库中再没有其他会话在此时要求执行该解析的 cursor 而已。

 

那么,这里有两个问题:

1.系统在问题时段出现那么多 'library cache lock'<='cursor: pin S wait on X' 阻塞关系正常吗?

 正常的!出现这么多不同的 chain 是因为各个 chain 涉及的 cursor 不相      同。

2.如上会话 628 又被谁阻塞了呢,这里为什么没有阻塞者呢?

不知道!没错,从这里看,会话 628 的阻塞者并不知道,同时,我们可以通过前面的 chain 信息搜索可以知道,绝大部分的 library cache lock 都没有找到阻塞者。

到这里,我们基本可以忽略 ’cursor:pin S wait on X’ 等待事件了,接下来需要解释的就是为什么会有 library cache lock 等待事件以及如何找到其阻塞者了。

恼人的 librarycache lock

目前,我们开始关注 library cache lock 等待事件;诸多会话等待在 library cache lock 等待事件上,却又没有阻塞者,我们最重要的首先是需要确定各会话是否都等待在同一个对象上,如果是同一个对象,那我们只需要针对一个会话或一个对象进行分析即可。如何确定是否等待同一对象,前面的等待事件介绍中,我们知道 p1 是其唯一标识,那么我们在 trace 文件中简单搜索一下关键字 “p1: 'handle address'=” 即可:

通过搜索结果可以看到,所有的等待分布在两个不同的 handle address 上,似乎是分布在两个不同的对象上;

两个对象,真的吗?不妨仔细确认一下:

我们通过分别等待在两个不同 handle address 的对象的具体信息,可以看到,两个 handle address 事实上是分布在两个不同的实例上的;那么,相同对象在两个实例中的 handle address 有可能会不一致吗?当然! handle address 作为一个地址信息,在不同的实例不一致也是理所当然的。 所以这里,我们完全有理由怀疑事实上整个系统中等待 library cache lock 的会话都是等待在同一个对象上。

 

这里似乎好像提醒了我们一点,这是一个 RAC 数据库;那么,这里我们可以说,这么多 library cache lock 等待事件没有最终的阻塞者,是因为阻塞关系跨了 RAC 节点了才没有再 dia0 文件中打出来么?我也不知道,这恼人的 library cache lock

The special one

找不到出路时,我们不妨将我们看过的信息再仔细捋一捋,在那些经意和不经意间,我们总会发现一些我们可以看到的不一样的信息;这里,我们也是一样:

再看看我们的等待 chain ,在众多相似的 chain 中,存在独特的那一个 chain 19 ,其中告诉我们有一个会话持有了 library cache lock 阻塞了另一个会话,我们不妨仔细来看看 chain 19

 

我们可以看到几个点:

    跨节点的阻塞关系在这里被打印出来了,所以不存在跨节点的等待无法被 dia0 分析的情况;

    我们发现 session 4062 请求 library cache lock p3 与其他的会话不一致;

    阻塞者 session 5539 长时间 ’not in a wait’ ,上一次等待已经是 61 分钟之前,这意味着会话 5539 已经持有 library cache lock ,并在 CPU 上运行了超过 61 分钟!基本可以确定是在做解析(以 S 模式持有 library cache lock ),而且解析过程中可能遭遇了 bug (为什么不是在做 DDL 操作?因为做 DDL 操作最终还是要操作非常多的数据块,在长达 60 分钟的过程中不会不产生任何等待的!)

那这里,我们需要进一步了解的是 library cache lock 等待事件的 p3 值对我们又什么帮助,实际上这个值中包含了 library cache 中对象的类型信息等,不过,在这里我们暂时不关注那些,我们唯一需要知道的是, p3 的最后一位实际上意味着请求 library cache lock 的模式,模式为 2 意味着 shared ,而模式为 3 意味着 exclusived ,也就是我们通常说的 S 模式和 X 模式; 那么,什么情况下会以 X 模式请求 librarycache lock   而什么情况下又会以 S 模式请求 library cache lock ? 以请求的对象时表为例,通常, 在解析涉及该表的语句时,会要以 S 模式请求该表的 librarycache lock ,而当需要对表做 DDL 操作时,因为表定义的变化,需要修改 library cache 中的信息,所以会需要以 X 模式请求 library cache lock ;同时,我们需要注意的容易忽略的一点是,在使用 dbms_stats 包操作表的统计信息时(如收集 / 删除 / 锁定等),虽然不会全程以 X 模式持有该表的 librarycache lock ,但是依然会在过程的某个极短时间范围中以 X 模式持有 librarycache lock

很显然一点, S 模式和 X 模式的 library cache lock 也是互斥的。

 

chain 19 的关系来看,要想避免这个等待链的出现,我们应该怀疑两个点:

    是什么情况会让一个会话持有 library cache lock 而后又长时间在 CPU 上运行达到 61 分钟不产生等待事件;

    在生产时间段内,为什么会有会话要以 X 模式请求对象的 library cache lock ,是在修改表定义?是在收集统计信息?

以上两点,就需要通过视图取出相关的 SQL 来进行具体分析了,这里的 trace 已经无法提供更多的信息了;

最开始的疑惑和最后的疑惑

再一次,回到我们一直疑惑的问题,就是其他以 S 模式请求 library cache lock 的会话的阻塞者到底是谁呢?跟 chain 19 有关系吗?查了一圈 MOS ,似乎没有找到 dia0 文件中 library cache lock 等待无阻塞者的情况;不过,我们可以大胆的假设下面情况:

    chain 19 所示,会话 5539 S 模式持有某对象的 library cache lock ,而会话 4062 因为 DDL 或收集统计信息以 X 模式请求该对象的 library cache lock

而第三个会话 628 再以 S 模式请求对象的 library cache lock 时,因为 library cache lock 也是作为一种 LOCK 来处理,有一个请求队列,当前面有 4062 会话在以 X 模式请求时,排在其后的会话 628 则认为 4062 会先请求到 X 模式的 LOCK ,于是此时,虽然数据库中只有会话以 S 模式持有对象的 library cache lock ,但是会话 628 仍然只能在等待;

那么,如何验证这一点,我们可以注意的一个点是:

看到 4062 会话已经等待了 4 11 秒,如果我们上面的假设成立,那么其他会话的等待 library cache lock 的时间就不应该多于 4 11 秒;我们只要搜索关键字 ’time in wait:’ 即可:

可以看到所有的其他等待都没有超过 4 11 秒的,所以,我们可以确认,在会话 4062 之前,系统中没有 library cache lock 等待,而且我们还确认了一点,那就是源头会话 5539 持有的 library cache lock S 模式的,否则,就不需要 4062 会话,它一样可以阻塞非常多的其他会话。

 

还有最后一点点的疑惑,那就是客户说的,系统一段一段时间的慢,那么读到这里,读者朋友们应该会很清楚了,我们可以看到, library cache lock 的等待会有一个超时时间,整个系统中以 X 模式请求 library cache lock 的会话并不多,此处,一旦 4062 会话等待超时,该会话则会退出,而其他会话则将继续解析,并执行成功;而类似 4062 会话的操作可能会在一段时间后重新来做;而在重启应用之后, 5539 会话也就消失了,即使再有 4062 这样的会话存在,也不会大规模的影响其他会话的正常执行,这也就是其最终恢复的原因了。

抛回给客户的信息

至此,我们通过分析 trace 文件,已经能得出基本结论,但是还有几个点需要由客户执行相关的 SQL 进行核查确认;在与客户微信沟通后我们的推断都得到了验证:

    关于两个 library cache lock handle address 指向的是否同一个对象?

是的,通过 x$kglobj 基表分别在两个节点查询即可确认,并且确认为一个应用表;

    会话 4062 (以 X 模式请求 library cache lock )在做什么?

通过历史视图查询其执行的 SQL 可以知道,该会话在收集表的统计信息,而且为定期收集;

    会话 5539 (以 S 模式持有 library cache lock 长达 60 分钟)在做什么?

通过历史视图查询其执行的情况可以确认,该会话当时正在解析一个从 JDBC 连接过来的拼接出来的超长 SQL ,遭遇 bug ,篇幅限制,此处不再赘述。

给我们的警示

这里,我们看看能给我们的警示是什么呢?这里看上去根源是 5539 会话遭遇的 bug ,但是我们从分析来看,如果没有 4062 这样的会话执行的操作,我们事实上在整个系统中也就只有 5539 会话本身会比较慢而已;

为什么客户会比较频繁的来收集表统计信息呢,原来,客户收集的这个表会在每天清空,而后在第二天上午有足够数据时,开始使用 crontab 的方式定期收集,这次,因为遭遇了 5539 会话的超长 SQL 而导致了问题;

那么,对于此种场景我们的建议是什么呢?

    针对某些业务场景,我们建议使用锁定统计信息的方式来保证统计信息的有效性;

    如果某些特殊场景,无法使用前期的统计信息,我们建议在原来 lock 的统计信息的寄出上使用 dbms_stats 包的 set 相关 procedure 来修正统计信息值;

总之,如果不是到迫不得已的情况,我们不建议在业务高峰期间频繁收集统计信息。 本文转载于中亦安图

相关推荐

热文推荐