另辟蹊径第二弹,时间规律里的秘密

墨墨导读:在上个月的数据技术嘉年华里,我做了名为《另辟蹊径:从其他角度去解决数据库问题》的案例分享,讲述了通过时间规律来解决系统故障的思路。结果,这两天又出了类似的案例。和大家分享一下解决这个新问题的过程。

作者简介

罗海雄:Oracle ACE-A,ITPUB论坛数据库管理版版主,2012 ITPUB全国SQL大赛冠军得主;资深的架构师和性能优化专家,对 SQL 优化和理解尤其深入;作为业内知名的技术传播者之一,经常出席各类技术分享活动;从开发到性能管理,有着超过10年的企业级系统设计和优化经验;曾服务于甲骨文公司,组织和主讲过多次《甲骨文技术开发人员日》和《Oracle圆桌会议》,在任职甲骨文公司之前,还曾经服务于大型制造企业中芯国际,具备丰富的制造行业系统架构经验。

故障背景

某客户的7*24的系统,在12/25 01:45, 突然发生卡顿。

(通常情况下,分享案例不会给出特精确的时间,这次不同,精确时间正是解决问题的关键)

初探虎穴:原因分析

首先,检查数据库的ASH裸数据,看看那一段时间的活动回话情况

select trunc(sample_time,'mi'),count(*) from v$active_session_history where to_char(sample_time,'yyyymmdd-hh24mi') like '20201225-01%' ;

果然,1:45有很高的活动回话。检查具体的等待事件

select sample_time,event,count(*) from v$active_session_history where to_char(sample_time,'yyyymmdd-hh24mi') between '20201225-0144' and '20201225-0146' group by sample_time,event order by sample_time,count(*)

可以看到,01:44:58处,有大量的cursor: pins S wait on X等待。而接下来,则是大量的library cache lock 和 library cache:mutex X.这三个等待事件,多数情况都是发生在硬解析上。

继续检查,发现这些event 其实都是同一个SQL导致的。SQL很简单,单表查询。

同时检查该SQL的执行次数,发现非常高。

而且,可以看到,在12/25凌晨1点,总执行次数有个重置的过程,显然,这个SQL在1:44:58 之前被invalidate了,随后发生了硬解析,而且解析并发很高,所以导致了大量的cursor: pins S wait on X、library cache lock 和 library cache:mutex X.

扑朔迷离:为什么被挤出去?

至此,故障的直接原因已经找出来了,就是某个并发非常高的SQL, 在1:44:58前被invalidate,后续的高并发解析导致了大量的cursor: pins S wait on X、library cache lock 和 library cache:mutex X.

但是,为什么这个SQL跑的好好的,会被挤出去呢?

一个SQL被挤出去的原因,主要有几个:

  • 发生DDL

  • 统计信息改变

  • 手动purge shared pool

  • 内存不够

逐个去分析。

发生DDL

select last_ddl_time from dba_objects where object_name = '&tname';

发现是几个月前的last_ddl_time

统计信息改变

select last_analyzed from dba_tables where table_name = '&tname';select last_analyzed from dba_indexes where table_name = '&tname';

同样是几个月前

手动purge

通过alter system flush shared_pool 或者 dbms_shared_pool.purge可以把SQL手动挤出shared pool.
但是,大半夜的,而且和客户也确认过,没有做过类似操作。

shared pool内存不够

本身该SQL执行次数这么高,肯定排在LRU的前端,不大可能因为内存不足被挤出去。

至此,似乎陷入僵局。

独辟蹊径:挖掘时间规律

这时候,现场工程师说了一句,几个月前(7/22),发生过一次类似的故障,也是同样的SQL,时间也差不多就是 半夜1:40-1:50之间。

这句话提醒了我,会不会存在某个特殊的时间规律,导致该SQL会周期性的被挤出去呢?

虽然挤出去了,但是,有时候,并不会挤得特别干净,于是,尝试去检查一下 V$SQL里面有没有之前的信息。

select sql_plan_baseline,first_load_time, last_load_time,inst_id,plan_hash_value from gv$sql order last_load_time

其中,last_load_time代表SQL解析的时间。一眼看去,大量的44分的时间点,存在时间规律应该是没有疑问了。

但是,总共有不同的几个时间。

最多的是 01:44(或者45),有5条记录

13:44, 有3条记录

另外分别有1条 09:28和 01:49。

考虑到这里面记录的是解析时间而不是挤出去的时间,对于最后两条记录,可以有解释。

10/01 的 09:28这个,检查了一下数据库启动时间:

select to_char(startup_time,'yyyymmdd-hh24miss') from gv$instance;

数据库正好是在10/1上午9点多点启动的,所以应用连进来之后初次解析,没问题。

01:49, 可以认为是稍微延迟了几分钟重新解析,也可以认为没什么问题。

13:44 呢,习惯用24小时制可能不是第一眼看出来,但是13:44 不就是 中午 1:44吗?所以,规律也是很清晰的。

所以,时间规律变成:某天的 凌晨 01:44 或者 中午 01:44, 该SQL可能会被挤出去。

会是12小时的规律吗?如果是12小时,这些时间隔得似乎有些远。

我们逐条数据观察,从最近的开始。

最近一次,12/25 01:44
往前一次,12/18 13:44 间隔 6.5天
再往前一次,12/05 13:44, 和上一次间隔 13天
再往前一次,11/16 01:44, 和上一次间隔 19.5天
。。。

暂停一下,13天岂不是就是2个6.5天,19.5天岂不是就是 3个6.5天, 写个SQL验证一下

select sql_plan_baseline,first_load_time, last_load_time,(to_date(last_load_time,'yyyy-mm-dd/hh24:mi:ss') - lag(to_date(last_load_time,'yyyy-mm-dd/hh24:mi:ss')) over (order by last_load_time)) pattern, inst_id,plan_hash_value from gv$sql order last_load_time

果然,另外几个分别是13 和 32.5, 也都是6.5天的倍数。(0.2天那个是10/1上午9点多重启导致)

也就是说,规律是:这个SQL, 每隔6.5天,就可能被挤出去!!!

于是,开始检查数据库的job, 操作系统的job, 应用的job。
但是,一无所获。

那么会不会是个数据库参数控制呢?
看看有没有哪个数据库隐含参数,值是 6.5天,或者 156小时,或者9360分钟,或者 561600秒,或者 561600000毫秒的。

select indx ,KSPPSTVL from x$ksppcv where KSPPSTVL in ('6.5','156','9360' ) or KSPPSTVL like '561600%' ;

同样一无所获。

峰回路转: 找到根因

这时候,我们注意到,这个SQL用了SQL Plan Baseline, 会不会和这个有关系?

检查一下这个SQL对应的SQL Plan Baseline的创建时间,以及这个时间是不是也存在与出现问题的时间是不是也存在6.5的规律。

SQL Plan Baseline2018年7/5 13:44创建的, 距离12/25 01:44正好是139个6.5天。看来,SQL Plan Baseline应该就是元凶了。

以6.5和SQL Plan Baseline 搜索support.oracle.com, 果然发现如下bug:

执行次数特高的SQL, 如果存在SQL Plan baseline, 就可能每 6.5天就被invalidate。

A frequently executing cursor that was built using a SQL plan baseline is invalidated at every 6.5 days .
If this cursor is heavily executed by a large number of concurrent users then spikes of "cursor: pin S wait X" / "library cache: mutex X" occur upon its invalidation every 6.5 days.
Rediscovery Notes: This may be suspected if all of the following apply: - The cursor has a plan baseline - The SQL is heavily concurrenly used - Spikes of "cursor: pin S wait X" / "library cache: mutex X" are seen on the cursor at widely spaced intervals (approximately every 6.5 days)
Workaround Disable SQL plan baseline used by the heavily executed cursor .

至此,真相大白。

结语

对于重复发生的故障,准确的识别其中的时间规律,找到准确的周期,可以有效帮助寻找问题的根因。

墨天轮原文链接:https://www.modb.pro/db/43139(复制到浏览器中打开或者点击“阅读原文”立即查看)

(0)

相关推荐