关于奇怪的并行进程分析(一)

在使用orabbix进行监控的时候，得益于使用 实时DB time监控的选项，对于几分钟内的性能抖动也能够狠容易的记录下来，而且会把这个监控的结果基本真实反应出来，不会随着两个快照的间隔被平均，这样性能问题的分析和排查如虎添翼，我直接通过性能抖动的情况就能够快速定位在哪个时间段内可能存在问题，然后借助ASH就可以得到一个更具有针对性的报告，可以精确到1分钟甚至秒级。
可以看到在早上的七点左右的时候还是有一些明显的性能抖动，DB time会瞬间提高。

这对于一个OLAP的系统来说还是有些不正常的。
并行session的情况如下，可以看到在问题发生的时间段里，产生了大量的并行session.

而且同时我也收到了orabbix的告警邮件。

监控项目: Session Active：153
*UNKNOWN*：*UNKNOWN*
------------------------------------
故障时间:2015.08.27-07:22:04
所以这个问题还是需要关注一下，这种情况就犹如给一个静坐的人用针突然扎一下，会出现很明显的性能抖动。
首先为了进一步验证，得到了在快照时间内的负载信息，可以看到在问题发生的时间内DB time还是蛮高的。
BEGIN_SNAP   END_SNAP SNAPDATE            DURATION_MINS     DBTIME
---------- ---------- --------------------------------- ---------- 
     36343      36344 27 Aug 2015 04:00              60         85
     36344      36345 27 Aug 2015 05:00              60        118
     36345      36346 27 Aug 2015 06:00              60        150
     36346      36347 27 Aug 2015 07:00              60        180
     36347      36348 27 Aug 2015 08:00              60        137
     36348      36349 27 Aug 2015 09:00              60        140
     36349      36350 27 Aug 2015 10:00              60         67
     36350      36351 27 Aug 2015 11:00              60          8
所以说得到了上面的信息，能够让我们更加清楚问题的背景和基本情况。

查看alert日志，在问题发生的时间段里，没有看到其它异常的信息。
Thu Aug 27 00:07:08 2015
Archived Log entry 63315 added for thread 1 sequence 688962 ID 0xa4527950 dest 1:
Thu Aug 27 00:07:23 2015
LNS: Standby redo logfile selected for thread 1 sequence 688964 for destination LOG_ARCHIVE_DEST_3
Thu Aug 27 00:07:32 2015
Archived Log entry 63317 added for thread 1 sequence 688963 ID 0xa4527950 dest 1:
Thu Aug 27 00:07:38 2015
Thread 1 advanced to log sequence 688965 (LGWR switch)
所以从数据库层面来说，可能没有什么明显的活动。
但是问题不可能无中生有，我们怎么去找到问题的根源呢，为了更加精确的定位问题，我们需要借助于ASH来还原那个时间段的问题情况。
为了排除Orabbix监控的延迟，我抓取的时间范围略大了些，是7分钟内的ash.
得到的报告如下，可以看到在问题发生的时间段内，取样数也确实蛮高的。

Sample Time	Data Source
Analysis Begin Time:	27-Aug-15 07:15:00	V$ACTIVE_SESSION_HISTORY
Analysis End Time:	27-Aug-15 07:22:05	V$ACTIVE_SESSION_HISTORY
Elapsed Time:	7.1 (mins)
Sample Count:	177
Average Active Sessions:	0.42
Avg. Active Session per CPU:	0.05

top user event为：

Event	Event Class	% Event	Avg Active Sessions
SQL*Net vector data from client	Network	39.55	0.16
Standby redo I/O	System I/O	2.26	0.01
RFS write	System I/O	1.13	0.00

所以对于这个问题的分析可能会有一定的难度，因为矛头似乎都指向了备库相关的问题。

对于等待事件SQL*Net vector data from client可以参考 Doc ID 1311281.1
说法是可以忽略。我们可以先把这个问题放一放，来通过其他的思路来分析一下。
首先数据库的负载突然提高，如果单纯是因为备库的原因，为什么不是其它时间段内，白天的时候没有任何报警。白天的负载更高，更应该出现问题才对。
所以这种情况应该还是有一定的触发条件，但是查看了crontab也没有什么发现，那么很可能就是scheduler相关的。
我们怎么来推论呢。
首先的考虑就是后台的scheduler，结果查看还是默认的晚上10点左右，所以到早上的那个时间段应该不会有直接的影响。
那么scheduler狠可能就是用户自定义的。
限定在问题时间段内，得到的信息如下
 select owner,job_name,last_start_date,end_date,NEXT_RUN_DATE from dba_scheduler_jobs where last_start_date between to_timestamp('2015-08-27 05:00:00','yyyy-mm-dd hh24:mi:ss') and to_timestamp('2015-08-27 08:00:00','yyyy-mm-dd hh24:mi:ss')
 OWNER   JOB_NAME                       LAST_START_DATE            
------- -------------- ---------------------------------------------
APP_TEST   SYN_D     27-AUG-15 07.11.00.002185 AM ASIA/SHANGHAI
APP_TEST   SYN_E      27-AUG-15 06.15.00.809059 AM ASIA/SHANGHAI
APP_TEST   SYN_F      27-AUG-15 06.12.05.312974 AM +08:00      
APP_TEST   SYN_G      27-AUG-15 05.00.40.797679 AM ASIA/SHANGHAI
可以看到确实还是有scheduler job在运行,而且时间也基本是相符的。
   LOG_ID LOG_DATE                                 OWNER      JOB_NAME                   STATUS  
---------- ---------------------------------------- ---------- -----------------------------------
    241839 27-AUG-15 07.30.00.140947 AM +08:00      TEST_APP   SYN_D                     SUCCEEDED
    241836 27-AUG-15 07.05.46.398691 AM +08:00      TEST_APP   SYN_E                     SUCCEEDED
    241840 27-AUG-15 07.30.01.319849 AM +08:00      TEST_APP   SYN_F                     SUCCEEDED
    241841 27-AUG-15 07.35.00.912152 AM +08:00      TEST_APP   SYN_G                     SUCCEEDED
从以上的信息可以猜想可能是scheduler job引发的大量并行session的情况，我们后续继续进行跟踪，揭开问题的真实面纱。