数据库负载急剧提高的应急处理(二)

对于之前碰到的一个数据库负载急剧提升的问题，做了应急处理之后，我们需要再冷静下来，来看看是哪些地方出现了问题，还需要哪些改进。
首先第一个问题就是为什么会突然负载提高，如果感觉，应该是业务层面出现了一些变化吧。当然没有数据，日志都是猜测。
我从监控中拿到了Zabbix监控的部分数据，发现在指定的时间点突然多了300多个进程。

    而在数据库的会话层面没有发现任何的抖动，这一点就很难解释的通了。
    系统级不会平白无故出现300多个进程，这些进程主要是在忙些什么，这些肯定说不通，我查看了问题时间段的报警。发现了这么一封报警信息。

ZABBIX-监控系统:
------------------------------------
报警内容: Alive xxxx_p
------------------------------------
报警级别: PROBLEM
------------------------------------
监控项目: Alive：0
------------------------------------
报警时间:2016.07.08-11:16:03
    如果是这样的情况就能说清楚了，在问题发生的时间段里，因为系统延迟，orabbix无法从服务端抓取到数据，所以出现了Alive的报警，而那个时间段的数据还是会参考之前的数据，而Zabbix是客户端的形式，在每台服务器上都有一个Agent，这些数据采集还是可以的，尽管延迟，但是还是会同步到服务端。因为我们是后续查看的历史信息。所以这样一来我们可以推理出来是在数据库层面多了300个多会话。
    而在业务层面去解释这个就比较困难了。首先业务层面的反馈是没有异常的调用情况。而系统层面反馈也没有发现特别的日志。这个工作就无形中落到了数据库层面。大家都希望我能够给出一些解释，能够从数据库层面得到一些分析的结果，毕竟这个问题是出现在数据库端。这让我联想起之前工作中的一个有意思的故事，有两个系统需要交互，系统会发数据到模块A,然后模块A会同步数据处理到模块B,以此类推，结果模块A的问题，模块A没有错误日志，模块B有错误日志，这下大家都集中在模块B，然后让他们提供更多的分析和解释，最后发现问题是模块A那边过来的，没有错误日志不证明没错误，在这种多系统交互中就会有很多额外的沟通成本。
    当然这个问题也不是猜测出来的，我来看看数据库端的情况。
    首先是SWAP的争用，为什么在问题时间段会突然出现争用很高的情况，之前没有吗，实际情况是之前也有的，但是不够明显，那问题出现之前SWAP情况怎么样呢。查看数据库日志发现了下面的一段。这么一段日志还是很有说服力的。
Archived Log entry 11780 added for thread 1 sequence 2581 ID 0xc5819545 dest 1:
Fri Jul 08 10:27:49 2016
WARNING: Heavy swapping observed on system in last 5 mins.
pct of memory swapped in [3.10%] pct of memory swapped out [0.54%].
Please make sure there is no memory pressure and the SGA and PGA
are configured correctly. Look at DBRM trace file for more details.
Fri Jul 08 10:28:13 2016
Thread 1 advanced to log sequence 2583 (LGWR switch)
  Current log# 7 seq# 2583 mem# 0: /U01/app/oracle/fast_recovery_area/STEST032/onlinelog/o1_mf_7_blsdlk1p_.log
Fri Jul 08 10:28:13 2016
所以可以充分说明问题集中爆发之前已经有了SWAP的争用情况。而后面的是一个集中的触发点，导致了SWAP的争用更加严重。
那么问题发生时到底是哪些SQL或者数据库层面的操作导致的问题呢，我一看快照，因为是杀掉进程重启，那个时间段刚好没有生成快照，导致了在问题发生时间段的ASH，AWR数据生成，所以只能看到之前一个小时的数据，我们可以作为一个参考。

SQL执行的大体情况如下。

SQL ID	PlanHash	Sampled # of Executions	% Activity	Row Source	% RwSrc	Top Event	% Event	SQL Text
ag4b2tb6yxscc	2802892098	219	31.29	MERGE	28.83	log file switch completion	24.86	MERGE INTO TEST_OPENPLATFORM_U...
ag4b2tb6yxscc	2802892098	219	31.29	TABLE ACCESS - BY INDEX ROWID	1.04	log file switch completion	1.04
134zhd24d9p0y		79	10.68	** Row Source Not Available **	10.68	log file switch completion	8.88	insert into TEST_USER_INFO (CI...
fw8tvzm9zc48g	2398546977	48	6.14	MERGE	5.01	log file switch completion	3.88	MERGE INTO CYUC_USER_LOGIN_TOK...
5nn5amat9hfjm	167343150	10	3.97	TABLE ACCESS - FULL	3.12	CPU + Wait for CPU	3.12	MERGE INTO TEST_OPENPLATFORM_B...
351tx6bsgk1un	4261754961	16	3.50	TABLE ACCESS - FULL	3.31	CPU + Wait for CPU	3.31	MERGE INTO TEST_GUEST_USER_INF...

看到这个这个报告，我有些迷惑了，不知道问题的瓶颈在哪里了，因为top 1的SQL本身已经优化过，已经是最优的方式了，执行频率要高一些，而下面的两个标黄的语句仔细查看，是存在性能隐患的语句，但是执行频率相对来说不高，占用的比例也不高。
这样一来问题的分析就有些茫然了。不过这边也在和应用同学做一些确认。让他们帮忙提供一些数据信息。其中部分的信息如下

      8点     9点     10点    11点    12点   
/test/master   46279   43135   51140   42276   38712  
/test/guest    1069    1313    1533    6148    1794  
看到这些数据，在问题发生时间点，主要的执行频率还下降了，看起来说明不了问题，不过有一点比较特别的就是/test/guest这个地方，平时的执行频率是1000，而在问题发生时间点是6000多，这个确实是有些特别。
而从之前时间段的AWR可以看出，执行频率还是1000多一些。

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
1,521.05	6,464	0.24	22.07	0.72	1.94	ag4b2tb6yxscc	JDBC Thin Client	MERGE INTO TEST_OPENPLATFORM_U...
69.84	1,980	0.04	1.01	6.77	8.20	5nn5amat9hfjm	JDBC Thin Client	MERGE INTO TEST_OPENPLATFORM_B...
507.27	1,304	0.39	7.36	3.32	0.00	351tx6bsgk1un	JDBC Thin Client	MERGE INTO TEST_GUEST_USER_INFO...

有了这些数据支撑，就可以明白问题的大体情况，原本系统的SWAP争用已有，但是最近比较严重，而在问题发生时间段里，问题更加严重，主要就是因为一个本来负载不是很高的SQL执行频率从1000多提升到了6000多，执行计划中显示是全表扫描，好几百万数据的大表来说还是很明显的问题。而对于这个语句的优化其实倒不是很难，关键有针对性的分析就尤为重要了。