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

数据和云

发布于 2021-02-08 14:57:34

4170

发布于 2021-02-08 14:57:34

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

作者简介

罗海雄：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 .

至此，真相大白。