前言:
我们曾经在 17 期,发布了 ” 看中国最美女 DBA 的一次价值连城的系统优化 ” 的文章 , 大家表示很 好看 。很多网友对什么时候可以再看到最美女 DBA 的文章表示严重的关注,为此,我们在 32 期再度邀请到中亦科技的小仙女为大家分享她的第二篇技术文章。
客户删除大量历史分区,越删越慢,同时系统出现性能问题,请求协助分析和解决。
如下图所示 , 红色底线表示执行时间 :
删除分区的时间从 1 秒钟变为 2 分钟,再到 5 分钟 …
如果是你,不妨停下来思考一下,你会怎么来分析这个问题呢?
同时看中亦最美女 DBA 又是如何分析和解决的 … (思考过后,下方有福利 … 照片?嘻嘻 … )
电话响了,“我们的系统好像出问题了,快帮我们看看吧。”
来电的客户是某大型央企政府机构,系统遍布全国各省,每天需要处理的 case 不断。
放下电话,远程连上,一切都是那么熟练和自然。
客户提到系统有问题,那就先收个 AWR 报告来看看吧。
看完吓一跳,确实如客户所说,系统出问题了!
对,性能问题。不过看上去好像问题不难。
估计是 DDL 语句引起的,难道这么简单就被判断出来了 ?... 嘻嘻
“ 你们是不是在做什么特殊的操作呀? ” 先简单了解一下。
“ 我们没做什么特殊的操作呀,我们就是在 做分区表历史分区的清理而已,前面删的好好的,突然系统就这样了 ,肯定跟我的删除没有关系! ” 客户答到。
这还叫没做什么操作啊 …
首先从 AWR 报告搜索 drop/truncate 关键字,
可以看到大量的 drop partition 操作,验证过了客户所说的删除历史分区操作的动作。
如下图所示,
脑子里立刻闪现出这么一个过程:
删除一个分区,相当于对表做了
DDL
操作;
对表做了
DDL
操作之后,与表相关的语句需要重新硬解析,解析过程中需要对相关表持有
S
模式的
library cache lock
;
删完一个分区紧接着删下一个分区,又要对表请求
X
模式的
library cache lock
;
后续再有语句又需要重新硬解析,这时请求不到
S
模式的
library cache lock
了;
往复循环,会导致等待越来越严重。因为不断
DDL
,不断有
SQL
需要硬解析,
DDL
和
SQL
硬解析分别持有
X
和
S
模式的
library cache lock,
二者不兼容,
S
阻塞
X,X
又阻塞了后续需要执行的
SQL
所需要的
S
,于是就出现了大量的
library cache lock
等待;对于日常业务需要执行的
SQL
语句而言,出现
LIBRARY CACHE LOCK
等待则会导致响应时间变慢,也就是客户所说的系统出问题了
..
cursor:pin S wait on X
等待则表示多个会话同一时刻执行一个
SQL
,发现需要做硬解析,则由其中一个会话负责硬解析,其他会话等待硬解析的结果,坐享其成就好了,不需要再做硬解析。也就是说,有多个会话再并发的执行同样的
SQL.
大概理清了这个过程之后,解决问题的思路就出来了:
再重复一下关键点:
不断 DDL 删除历史分区,不断有 SQL 需要硬解析; DDL 和 SQL 硬解析分别持有 X 和 S 模式的 librarycache lock, 二者不兼容, S 阻塞 X,X 又阻塞了后续需要执行的一堆 SQL 所需要的 S , 这一堆 S 势必会导致再接下来的 DDL 所需要的 X 的被阻塞的更久,于是就出现了大量的 library cache lock 等待。
需要说明的是,硬解析应该是很快的一个动作, 只要不是删完一个分区再立刻删除一个分区 ,业务的影响就可以基本忽略不计了;
谁说女子不如男,被自己的聪明感动到了,嘻嘻 …
于是我乐颠乐颠地跟客户说道: “ 你可以在删除分区的过程中加一个 sleep 操作,不要这么连续地删除分区!应该可以解决这个问题! ”
客户试了试,很快给了答复, “ 删除分区是变快了,但现在是系统出问题了,肯定不是我删分区造成的!你快查查是不是系统有问题了。
显然,系统出现的这些问题和之前清理历史分区操作有关。
和客户耐心解释后,客户还是有疑问:
Q:“如果真的跟删除分区有关,为什么我前面那些表删除分区的时候那么快
?
”
的确,很尖锐的一个问题。
A:“可能是前面删除历史分区的时候,业务上没有什么其他
SQL
在执行吧。”
Q:“那为什么删除第一个分区的时候还好好的,到了后面就慢了呢?”
A:“因为删第一个分区的时候,还没有会话在做硬解析嘛。”
为了让客户信服,我从 AWR 报告里摘取下图
可以看到,和平时相比,出现了大量的硬解析 , 见 Invali-dations 和 Reloads 。
思考片刻后,我再次提出我的建议:
“
那要不咱们换个时间来删除,找个闲一点的时候,避免业务高峰,速度肯定能加快!
”
这是一个放之四海都适用的运维原则,没想到,客户似乎有些不耐烦了:
“
我们这个系统是
24
小时都很忙,没有所谓闲的时候!如果是像你说的问题,那你有没有办法帮我们解决现在删除分区慢的问题,还有很多分区需要删除呢;
可否在业务不停的情况下,我们可不可以让它优先删除分区,再做硬解析?
”
听到这话,我的内心是奔溃的 ……(此处不用图是不能表达作者的心情的!)
然而,客户是上帝啊,有问题自然需要快速解决,才能显示我们服务的价值。
那么,我们不妨试试看, 可否在业务不停的情况下,我们可不可以让它优先删除分区,再做硬解析呢?
真以为有啊,逗你玩呢 .. 嘻嘻
于是,我跟客户要了一份他们删分区的命令,准备自己执行试试看。
拿着客户的删除命令, 我就开始执行:
第一个分区的删除操作还是挺快的,不到一秒的时间就完事了;
随后第二个分区的删除就慢了,和我预想的一样,是在等待 library cache lock 事件,
估计一小会儿就完,只要我不立刻就继续执行删除分区的操作应该就问题不大,先等着吧。
。。。。。。
然而,等了有好几分钟,这个分区的删除操作才完成,这 … 什么情况?
读者到这里不妨停下来,思考一下,如果是您,你会怎么继续分析 …
…
…
…
…
…
…
看起来,问题还真不一定是想象的那样 :
可以判断删除分区的操作是被解析阻塞了,
但是真的需要阻塞那么久吗?
接下来我通过 gv$session 视图的 blocking_session 字段和 sid 字段的迭代跟进,
终于找到了阻塞的源头,是一个 select 语句 , 脱敏后如下所示:
这个会话阻塞 DDL 语句,显然这个语句正在做解析操作;正常解析应该是非常快的动作,然而这个解析却一直在做,而且从 gv$session.event 不断刷等待事件上看一直在等待不同的 IO ,那它到底在做什么呢?
我这个时候想起了平日里师父们培训时讲的递归 SQL 这回事,在解析的时候,它实际上在底层调用的是递归 SQL ,那现在就需要将它抓出来!
于是,我抓了一个 process dump ,相关的递归 SQL 现出了原型:
没错,当前实际上执行的 SQL 是 130dvvr5s8bgn ;
再通过抓取这个 SQL 的 10046 可以看到其等待情况类似如下:
大多数等待事件均为数据文件顺序读;
看起来就是这个 SQL 的执行时间太长,导致的解析时间过长!
具体的
SQL
文本如下:
select obj#,dataobj#, part#, hiboundlen, hiboundval, ts#, file#, block#, pctfree$,pctused$, initrans, maxtrans, flags, analyzetime, samplesize, rowcnt, blkcnt,empcnt, avgspc, chncnt, avgrln, length(bhiboundval), bhiboundval from tabpart$ where bo# = :1order by part#;
那么这个 SQL 为什么执行的这么慢呢?立刻来做个 SQLRPT 看看:
从 SQLRPT 可以看到, SQL 语句似乎没有那么复杂,但是 SQL 语句平均单次执行时间需要超过 60 秒,其中物理读的个数为 7664 个,而 IO 等待事件达到了 126 秒!由于执行计划走索引范围扫描,等待事件是单块读,相当于每个 IO 需要 16ms ,这个 IO 性能本身不太好啊!
这个系统性能本身就差,再系统上做这种影响生产的动作,那不就更慢了吗?
问题到这里就算结束了么?
正准备跟客户汇报这一重大发现,
但是一想到这个过程还是难以解释清楚客户的疑问,我隐约觉得我还是应该再做点什么;
这里,看起来语句的执行计划不错,但是真的要那么多物理读吗?
而且每次都需要做那么多物理读吗?数据怎么就不缓存到 SGA 里呢?
于是,我就在刚刚的 10046 中 trace 文件中找到这里 bo# 对应的绑定变量值,自己手动执行:
哇,这速度简直快的不要不要的!
怎么到了硬解析那里就要做那么多物理读然后就变的慢了呢?
IO 你慢就慢吧,怎么我的递归 SQL 还要经常做那么多物理读呢?
越往下查,就有太多的问题需要解释了 …
先后继续删了好几个分区,还都是这样的情况!
SQL 的硬解析真是慢到不可接受。但是我继续看 SQL 解析过程的等待时发现其发生 IO 等待时所等待的对象(v$session.row_wait_obj#)正是我删除的那个分区表!
如此下来,更是诡异了,语句在做硬解析执行 130dvvr5s8bgn 访问的是 TABPART$ 及其表上的索引, 怎么会去访问根本就不在执行计划中的对象呢?
气死本姑娘了!今天怎么回事,这么多奇葩请出现呢。告诉自己,不能乱,不能乱。再静下心来仔细研究了一刻钟后,我使出了大招:
altersystem set events '14534 trace name context forever, level 1';
接下来,我再次开始删除分区;这个时候,奇迹出现了:
删除操作异常顺利,平均每个分区 1 秒左右就删除完了;
这时,终于可以理直气壮地向客户好好解释此中的问题,接下来的工作就继续甩给客户了;
看到这里,很多读者蒙圈了。
怎么你就出了这么个大招了呢?姑娘,中间到底经历了什么..
公司平日里各位师父们的培训,不断强调过,如果你觉得不合理的地方,想破脑袋也想不明白的,那么就有可能是不合理的地方,可能就是oracle的缺陷。所以,期间我只是登录MOS网站,以 TABPART$ 作为搜索的关键字,简单一搜索,搜到如下 bug :
bug文档中提到,出现这种情况是因为表没有收集统计信息,导致解析时需要扫描extent map(非动态采样);而使用14534事件来跳过extent map,避免load library cache data的时间过长,避免解析时间过长;
要匹配这个 bug ,我还需要核对:
1. 删除的分区表上是否有统计信息?
2. 数据库的版本是不是一致的?
首先,查看表的信息发现这个分区表从未收集过统计信息,符合!
然而, bug 提到的数据库版本是 10g ,而我们这里的数据库版本是 11.2.0.3, 为什么会出现这个情况呢?
这里,小亦姑娘教大家一招(不用谢哈)...
不妨看看上面 BUG 的描述,细节,注意细节。
“Thisfix is disable by default” 。一切尽在不言中了吧 …
