關於奇怪的並行程序分析(一) (r6筆記第41天)
在使用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
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)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的情況，我們後續繼續進行跟蹤，揭開問題的真實面紗。