備庫報警郵件的分析案例（二)
在第一篇中分享了關於備庫報警郵件的分析，發現很多問題都是一環扣一環.
起初是透過監控主庫中的v$dataguard_status發現備庫中可能存在一些問題，結果逐步分析，發現是由備庫的crontab觸發了備庫的定時read-only和online狀態，（即只讀和應用日誌，10gR2的環境），而這些關鍵資訊都是從資料庫的alert日誌中發現的，但是問題還沒有完，才剛剛開始，因為發現備庫中竟然有ORA-1652: unable to extend temp segment by 128 in tablespace的錯誤，這在備庫中著實是很奇怪的，備庫在read-only狀態時會有什麼樣的sql語句對於temp消耗如此之大？透過對比主備庫發現，主庫僅僅為32G，而備庫卻有近98G大小，而且從歷史記錄來看，這個錯誤一致存在，也算是一個歷史遺留問題吧。
透過分析temp的空間佔用情況，發現系統級的磁碟空間確實也不夠了。目前只保留了20G左右，如果系統出現了大的業務抖動，這備庫的空間使用是岌岌可危的。
在暫時沒有辦法去換取硬體的情況下，就可以考慮刪除兩個臨時資料檔案，但是這個時候就需要明白為什麼備庫要3個臨時資料檔案，這種使用是否合理，是不是哪裡出了問題。
對於這個問題，自己也走了一點彎路，那就是透過ash的思路來分析。
在備庫中抓取了問題時間段裡的ash報告，發現下面兩條sql貌似佔有了一定的比例。
Top SQL Statements
top1的語句為
SELECT * FROM TEST_CN_BIND WHERE CN=:1 AND CN_TYPE IN(1, 2, 3) AND ENAABLED='Y' ORDER BY CN_TYPE
執行計劃為：
Execution Plan
-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 3 (100)| |
| 1 | SORT ORDER BY | | 1 | 43 | 3 (34)| 00:00:01 |
| 2 | TABLE ACCESS BY INDEX ROWID| TEST_CN_BIN | 1 | 43 | 2 (0)| 00:00:01 |
| 3 | INDEX RANGE SCAN | IDX_CN_BIND_CN | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------
透過這個也著實看不出有什麼問題了，top 2的語句也是類似的情況。
這個時候就有些迷茫了，到底是什麼原因導致了temp的過度使用。
這個問題回過頭來看，首先要明白什麼操作可能會消耗大量的temp，使用temp的場景有下面幾種
- 索引建立或重建立.
- ORDER BY or GROUP BY
- DISTINCT 操作.
- UNION & INTERSECT & MINUS 等集合運算
- Sort-Merge joins.
- Analyze 操作
--其它異常
那麼到底可能是什麼原因呢，檢視了所有的top sql發現只有top1的語句含有order by的字樣，但是透過執行計劃來分析，卻實在分析不出來更多的資料，因為確實走了索引，這個索引列重複值極低，所以order by的代價非常小，儘管執行頻率極高，有大概百萬的呼叫次數
Stat Name Statement Per Execution % Snap
------------------------------------ -------------- -------
Elapsed Time (ms) 760,955 0.8 40.6
CPU Time (ms) 80,327 0.1 11.7
Executions 1,007,536 N/A N/A
Buffer Gets 4,223,066 4.2 52.4
Disk Reads 110,754 0.1 45.3
Parse Calls 1,007,396 1.0 40.0
Rows 185,860 0.2 N/A
User I/O Wait Time (ms) 684,686 N/A N/A
Cluster Wait Time (ms) 0 N/A N/A
Application Wait Time (ms) 0 N/A N/A
Concurrency Wait Time (ms) 0 N/A N/A
Invalidations 0 N/A N/A
Version Count 8 N/A N/A
Sharable Mem(KB) 127 N/A N/A
所以看著這個報告，讓人著實摸不著頭腦，這個時候也不能風風火火開始調優，既然自己都說不通自己，那麼到底是怎麼消耗的temp,這些還是需要找到靠譜的理由來。
而temp的使用情況是一個動態的過程，所以直接透過歷史檢視等等是無從知曉的。
我們可以使用手工監控的方式來做。
第一個指令碼為：
語句為check_temp.sh
##check_temp.sh
function get_temp_usage
{
sqlplus -s / as sysdba <<EOF
set time on
set pages 100
set linesize 200
col sysdate format a10
col username format a15
col sid format 9999
col serial# format 99999
col blocks format 99999999
col sql_text format a70
set feedback off
select systimestamp from dual;
set feedback on
SELECT sysdate,a.username, a.sid, a.serial#, a.osuser, b.blocks, c.sql_text
FROM v\$session a, v\$sort_usage b, v\$sqlarea c
WHERE b.tablespace = 'TEMP'
and a.saddr = b.session_addr
AND c.address= a.sql_address
AND c.hash_value = a.sql_hash_value
AND b.blocks*8192 > 0
ORDER BY b.tablespace, b.blocks;
EOF
}
get_temp_usage
第二個就是個種子程式來呼叫，給定10秒的輪詢。
$ cat tmp.sh
for i in {1..36000}
do
sh check_temp.sh >> check_temp.log
sleep 10
done
這種守株待兔的方式看起來不是很靈活，但是著實有效。
昨晚寫好之後來看，早上收網就發現有收穫了。發現在早晨的特定時間段裡，有兩個session在執行同樣的sql語句，語句的temp使用起初不大。都是4000多個block,大概是31M
SYSTIMESTAMP
-----------------------------------------------------
11-NOV-15 06.00.21.907858 AM +08:00
SYSDATE USERNAME SID SERIAL# OSUSER BLOCKS SQL_TEXT
---------- ---------- ----- ------- ------------------ ----------------------------------------------------------------------
2015-11-11 TEST_SHINK 6553 47693 webadmin 4352 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:00:21 bled='Y' group by cn having count(cn)>1) t, cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
2015-11-11 TEST_SHINK 6533 60000 webadmin 4480 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:00:21 bled='Y' group by cn having count(cn)>1) t, cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
但是繼續往下看，就發現這個問題就開始突出了。
SYSDATE USERNAME SID SERIAL# OSUSER BLOCKS SQL_TEXT
---------- --------------- ----- ------- -------- ------- ----------------------------------------------------------------------
2015-11-11 TEST_SHINK 6553 47693 webadmin 3302400 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:57:37 bled='Y' group by cn having count(cn)>1) t, test_cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
2015-11-11 TEST_SHINK 6533 60000 webadmin 3302400 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:57:37 bled='Y' group by cn having count(cn)>1) t, test_cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
按照這個量級和使用情況，一條語句需要消耗的temp大小為近26G,兩條sql佔用的就是52G
SQL> select 3302400*8192/1024/1024 size_MB from dual;
SIZE_MB
----------
25800
聽起來似乎還是有餘地，不是配置了98G的temp空間嗎，應該還夠用，但是繼續往下看就發現後面還會有其它的session進來。最多的時候差不多8個，這樣計算的話，98G的空間也是不夠的。
來看看這個語句的資源消耗，預估是近18G的temp使用。
----------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)|
----------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 29M| 1654M| | 5361K (4)|
| 1 | SORT ORDER BY | | 29M| 1654M| 2032M| 5361K (4)|
|* 2 | HASH JOIN | | 29M| 1654M| 1037M| 4941K (4)|
| 3 | VIEW | | 29M| 700M| | 2696K (5)|
|* 4 | FILTER | | | | | |
| 5 | HASH GROUP BY | | 29M| 756M| 19G| 2696K (5)|
|* 6 | TABLE ACCESS FULL|TEST_CN_BIND| 587M| 14G| | 898K (5)|
|* 7 | TABLE ACCESS FULL |TEST_CN_BIND| 587M| 18G| | 898K (5)|
----------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T"."CN"="C"."CN")
4 - filter(COUNT(*)>1)
6 - filter("ENABLED"='Y')
7 - filter("C"."ENABLED"='Y')
有同事提問是否這個語句存在並行的可能性，顯然是不會的，一來從執行計劃中沒有任何痕跡，二來如果是並行，session應該同時被監控出來，而不是後面逐步多起來。
這條語句如果細看還是存在一定的問題，這麼大的表引用了兩次同一個大表，其實完全可以改寫為更簡單的形式
select c.cn as cn,c.uin from test_cn_bind c where enabled='Y' group by c.cn,c.uin having count(c.cn) >1;
當然這個時候在備庫中還是可以考慮使用並行資源的。
可能到這個時候問題的分析就到此為止了，就可以質問開發的同學，為什麼寫出這麼消耗資源的語句來，然後把他們痛批一頓，其實還真不是這樣，而且這樣也沒有找到根本的原因，為什麼需要這個查詢，這是基於什麼樣的需求等等，其實還有很多需要改進的東西，比如在10g版本中備庫的ash其實就是主庫的這些資訊，在11g以後就可以獨立檢視備庫的ash了。在下一個章節繼續再說這個問題的由來和改進。
起初是透過監控主庫中的v$dataguard_status發現備庫中可能存在一些問題，結果逐步分析，發現是由備庫的crontab觸發了備庫的定時read-only和online狀態，（即只讀和應用日誌，10gR2的環境），而這些關鍵資訊都是從資料庫的alert日誌中發現的，但是問題還沒有完，才剛剛開始，因為發現備庫中竟然有ORA-1652: unable to extend temp segment by 128 in tablespace的錯誤，這在備庫中著實是很奇怪的，備庫在read-only狀態時會有什麼樣的sql語句對於temp消耗如此之大？透過對比主備庫發現，主庫僅僅為32G，而備庫卻有近98G大小，而且從歷史記錄來看，這個錯誤一致存在，也算是一個歷史遺留問題吧。
透過分析temp的空間佔用情況，發現系統級的磁碟空間確實也不夠了。目前只保留了20G左右，如果系統出現了大的業務抖動，這備庫的空間使用是岌岌可危的。
在暫時沒有辦法去換取硬體的情況下，就可以考慮刪除兩個臨時資料檔案，但是這個時候就需要明白為什麼備庫要3個臨時資料檔案，這種使用是否合理，是不是哪裡出了問題。
對於這個問題，自己也走了一點彎路，那就是透過ash的思路來分析。
在備庫中抓取了問題時間段裡的ash報告，發現下面兩條sql貌似佔有了一定的比例。
Top SQL Statements
| SQL ID | Planhash | % Activity | Event | % Event | SQL Text |
|---|---|---|---|---|---|
| 672161835 | 34.48 | db file sequential read | 27.59 | SELECT * FROM TEST_CN_BIND WHERE CN... | |
| CPU + Wait for CPU | 6.90 |
|
|||
| 935831560 | 17.24 | db file sequential read | 15.52 | SELECT CN_MASTER, PASSWD, BIND... |
top1的語句為
SELECT * FROM TEST_CN_BIND WHERE CN=:1 AND CN_TYPE IN(1, 2, 3) AND ENAABLED='Y' ORDER BY CN_TYPE
執行計劃為：
Execution Plan
-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 3 (100)| |
| 1 | SORT ORDER BY | | 1 | 43 | 3 (34)| 00:00:01 |
| 2 | TABLE ACCESS BY INDEX ROWID| TEST_CN_BIN | 1 | 43 | 2 (0)| 00:00:01 |
| 3 | INDEX RANGE SCAN | IDX_CN_BIND_CN | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------
透過這個也著實看不出有什麼問題了，top 2的語句也是類似的情況。
這個時候就有些迷茫了，到底是什麼原因導致了temp的過度使用。
這個問題回過頭來看，首先要明白什麼操作可能會消耗大量的temp，使用temp的場景有下面幾種
- 索引建立或重建立.
- ORDER BY or GROUP BY
- DISTINCT 操作.
- UNION & INTERSECT & MINUS 等集合運算
- Sort-Merge joins.
- Analyze 操作
--其它異常
那麼到底可能是什麼原因呢，檢視了所有的top sql發現只有top1的語句含有order by的字樣，但是透過執行計劃來分析，卻實在分析不出來更多的資料，因為確實走了索引，這個索引列重複值極低，所以order by的代價非常小，儘管執行頻率極高，有大概百萬的呼叫次數
Stat Name Statement Per Execution % Snap
------------------------------------ -------------- -------
Elapsed Time (ms) 760,955 0.8 40.6
CPU Time (ms) 80,327 0.1 11.7
Executions 1,007,536 N/A N/A
Buffer Gets 4,223,066 4.2 52.4
Disk Reads 110,754 0.1 45.3
Parse Calls 1,007,396 1.0 40.0
Rows 185,860 0.2 N/A
User I/O Wait Time (ms) 684,686 N/A N/A
Cluster Wait Time (ms) 0 N/A N/A
Application Wait Time (ms) 0 N/A N/A
Concurrency Wait Time (ms) 0 N/A N/A
Invalidations 0 N/A N/A
Version Count 8 N/A N/A
Sharable Mem(KB) 127 N/A N/A
所以看著這個報告，讓人著實摸不著頭腦，這個時候也不能風風火火開始調優，既然自己都說不通自己，那麼到底是怎麼消耗的temp,這些還是需要找到靠譜的理由來。
而temp的使用情況是一個動態的過程，所以直接透過歷史檢視等等是無從知曉的。
我們可以使用手工監控的方式來做。
第一個指令碼為：
語句為check_temp.sh
##check_temp.sh
function get_temp_usage
{
sqlplus -s / as sysdba <<EOF
set time on
set pages 100
set linesize 200
col sysdate format a10
col username format a15
col sid format 9999
col serial# format 99999
col blocks format 99999999
col sql_text format a70
set feedback off
select systimestamp from dual;
set feedback on
SELECT sysdate,a.username, a.sid, a.serial#, a.osuser, b.blocks, c.sql_text
FROM v\$session a, v\$sort_usage b, v\$sqlarea c
WHERE b.tablespace = 'TEMP'
and a.saddr = b.session_addr
AND c.address= a.sql_address
AND c.hash_value = a.sql_hash_value
AND b.blocks*8192 > 0
ORDER BY b.tablespace, b.blocks;
EOF
}
get_temp_usage
第二個就是個種子程式來呼叫，給定10秒的輪詢。
$ cat tmp.sh
for i in {1..36000}
do
sh check_temp.sh >> check_temp.log
sleep 10
done
這種守株待兔的方式看起來不是很靈活，但是著實有效。
昨晚寫好之後來看，早上收網就發現有收穫了。發現在早晨的特定時間段裡，有兩個session在執行同樣的sql語句，語句的temp使用起初不大。都是4000多個block,大概是31M
SYSTIMESTAMP
-----------------------------------------------------
11-NOV-15 06.00.21.907858 AM +08:00
SYSDATE USERNAME SID SERIAL# OSUSER BLOCKS SQL_TEXT
---------- ---------- ----- ------- ------------------ ----------------------------------------------------------------------
2015-11-11 TEST_SHINK 6553 47693 webadmin 4352 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:00:21 bled='Y' group by cn having count(cn)>1) t, cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
2015-11-11 TEST_SHINK 6533 60000 webadmin 4480 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:00:21 bled='Y' group by cn having count(cn)>1) t, cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
但是繼續往下看，就發現這個問題就開始突出了。
SYSDATE USERNAME SID SERIAL# OSUSER BLOCKS SQL_TEXT
---------- --------------- ----- ------- -------- ------- ----------------------------------------------------------------------
2015-11-11 TEST_SHINK 6553 47693 webadmin 3302400 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:57:37 bled='Y' group by cn having count(cn)>1) t, test_cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
2015-11-11 TEST_SHINK 6533 60000 webadmin 3302400 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:57:37 bled='Y' group by cn having count(cn)>1) t, test_cn_bind c where t.cn = c.c
n and c.enabled='Y' order by cn
按照這個量級和使用情況，一條語句需要消耗的temp大小為近26G,兩條sql佔用的就是52G
SQL> select 3302400*8192/1024/1024 size_MB from dual;
SIZE_MB
----------
25800
聽起來似乎還是有餘地，不是配置了98G的temp空間嗎，應該還夠用，但是繼續往下看就發現後面還會有其它的session進來。最多的時候差不多8個，這樣計算的話，98G的空間也是不夠的。
來看看這個語句的資源消耗，預估是近18G的temp使用。
----------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)|
----------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 29M| 1654M| | 5361K (4)|
| 1 | SORT ORDER BY | | 29M| 1654M| 2032M| 5361K (4)|
|* 2 | HASH JOIN | | 29M| 1654M| 1037M| 4941K (4)|
| 3 | VIEW | | 29M| 700M| | 2696K (5)|
|* 4 | FILTER | | | | | |
| 5 | HASH GROUP BY | | 29M| 756M| 19G| 2696K (5)|
|* 6 | TABLE ACCESS FULL|TEST_CN_BIND| 587M| 14G| | 898K (5)|
|* 7 | TABLE ACCESS FULL |TEST_CN_BIND| 587M| 18G| | 898K (5)|
----------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T"."CN"="C"."CN")
4 - filter(COUNT(*)>1)
6 - filter("ENABLED"='Y')
7 - filter("C"."ENABLED"='Y')
有同事提問是否這個語句存在並行的可能性，顯然是不會的，一來從執行計劃中沒有任何痕跡，二來如果是並行，session應該同時被監控出來，而不是後面逐步多起來。
這條語句如果細看還是存在一定的問題，這麼大的表引用了兩次同一個大表，其實完全可以改寫為更簡單的形式
select c.cn as cn,c.uin from test_cn_bind c where enabled='Y' group by c.cn,c.uin having count(c.cn) >1;
當然這個時候在備庫中還是可以考慮使用並行資源的。
可能到這個時候問題的分析就到此為止了，就可以質問開發的同學，為什麼寫出這麼消耗資源的語句來，然後把他們痛批一頓，其實還真不是這樣，而且這樣也沒有找到根本的原因，為什麼需要這個查詢，這是基於什麼樣的需求等等，其實還有很多需要改進的東西，比如在10g版本中備庫的ash其實就是主庫的這些資訊，在11g以後就可以獨立檢視備庫的ash了。在下一個章節繼續再說這個問題的由來和改進。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/23718752/viewspace-1829630/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 備庫報警郵件的分析案例（一)
- 備庫報警郵件的分析案例(三)
- 一封備庫報警郵件的分析
- 由報警郵件分析發現的備庫oracle bugOracle
- 三封報警郵件的分析
- 一條關於swap爭用的報警郵件分析(二）
- 一條看似平常的報警郵件所做的分析
- zabbix郵件報警通知
- grafana的郵件報警AlertingGrafana
- prometheus配置MySQL郵件報警PrometheusMySql
- 一條關於swap爭用的報警郵件分析
- zabbix郵件報警功能的驗證
- 一條關於swap爭用的報警郵件分析(一）
- zabbix 配置傳送郵件報警
- 使用Zabbix服務端本地郵箱賬號傳送報警郵件及指定報警郵件操作記錄服務端
- jenkins郵件報警機制配置Jenkins
- oracle資料庫自動發郵件實現報警功能Oracle資料庫
- SQLServer郵件預警SQLServer
- pinpoint-docker開啟郵件報警和整合釘釘報警推送Docker
- 細述zabbix郵件報警常見問題
- supervisor守護程式並配置郵件報警
- 一則備庫CPU報警的思考
- zabbix監控之同時向多人郵件報警
- Linux 下如何用 mutt 設定郵件報警Linux
- UNIX系統高負載郵件報警指令碼負載指令碼
- 醫療行業郵件營銷案例分析行業
- 表空間郵件預警(luckyfriends)
- 伺服器磁碟監控指令碼分享（含報警郵件）伺服器指令碼
- 基於Nginx+Keepalived的LB服務監控（郵件報警）Nginx
- 配置Jenkins構建失敗觸發郵件報警機制Jenkins
- X站釣魚郵件應急響應案例分析
- 技術分享| 如何使用Prometheus實現系統監控報警郵件通知Prometheus
- linux通過cacti監控apache通過飛信郵件進行報警LinuxApache
- Java Mail 郵件傳送（二）：簡單封裝的郵件傳送JavaAI封裝
- Laravel 傳送郵件報錯Laravel
- 分散式監控系統Zabbix-3.0.3-完整安裝記錄（5）-郵件報警部署分散式
- 郵件營銷工具具備的功能優勢？
- CentOS 6.4+Nagios+Msmtp+Mutt郵箱報警CentOSiOS