crontab導致CPU異常的問題分析及處理

今天檢視資料庫負載沒有發現問題，但是當我使用top命令的時候，發現有一個程式佔用了大量的cpu資源而且已經執行很長時間了。這一下子引起了我的注意。
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND  
25807 oraccbs1  25   0  8728  732  564 R 100.0  0.0   2021:19 /bin/sh -c /opt/app/oracle/xxxxxx/Script/DailyChk/chk_path_full.ksh PRODB 2>&1 >/opt/app/oracle/Script/DailyLog/chk_path_full.log 
13578 oraccbs1  18   0 40.2g  49m  29m D 61.0  0.0   6:40.18 oraclePRODB (LOCAL=NO)
17085 oraccbs1  18   0 40.2g  48m  24m R 40.6  0.0  36:44.43 oraclePRODB (LOCAL=NO)
30894 oraccbs1  18   0 40.3g  56m  27m D 38.1  0.0  54:40.46 oraclePRODB (LOCAL=NO) 
10616 oraccbs1  18   0 40.3g  54m  24m R 36.8  0.0  28:15.49 oraclePRODB (LOCAL=NO)
17089 oraccbs1  18   0 40.2g  49m  25m R 36.8  0.0  60:11.90 oraclePRODB (LOCAL=NO)
12103 oraccbs1  18   0 40.2g  31m  22m R 35.6  0.0 149:38.06 oraclePRODB (LOCAL=NO)
30898 oraccbs1  18   0 40.2g  50m  32m D 35.6  0.0  56:03.90 oraclePRODB (LOCAL=NO)

對於這個指令碼我比較陌生，一般這些維護性的工作主要都是客戶來做的。嘗試檢視了下這個指令碼的內容，發現是一個檢測指令碼，
指令碼的內容很清晰,是來監控歸檔目錄和home目錄的空間使用情況，當超過閥值的時候，就傳送簡訊給響應的人來處理。
內容大體如下：
#Send Short Message  if %used greater than 80% : ARCHIVE
        PERC_ARCH_USED=`df -P ${ARCH_PATH}|awk '{ print $5 }'|grep "%"|tr -d "%"`
        export casename=`uname -n`_${database}_Percent_Archive_Used_IS_${PERC_ARCH_USED}
        if [[ $PERC_ARCH_USED -gt 80 ]]; then
        sqlplus -s xxxxx @$myDir/Sql/sendsms.sql $casename
        fi


#Send Short Message  if %used greater than 80% : $ORACLE_HOME
        PERC_HOME_USED=`df -P ${HOME_PATH}|awk '{ print $5 }'|grep "%"|tr -d "%"`
        export casename=`uname -n`_${database}_Percent_HOME_Used_IS_${PERC_HOME_USED}
        if [[ $PERC_HOME_USED -gt 80 ]]; then
        sqlplus -s xxxxxx @$myDir/Sql/sendsms.sql $casename
        fi

這樣一個指令碼的執行肯定執行一次就完了。它是從哪裡執行的呢，首先想到的就是crontab。
crontab是在系統級作為作業自動執行的利器，可以進行各種細粒度的配置，使用也很方面。
先來檢視一下crontab的情況，結果在crontab的最後發現一個配置就是正在執行的job.
>crontab -l
#------------------------------------------------
# Test Log DB for house keeping .....
#------------------------------------------------
#0,30 * * * * /opt/app/oracle/xxxxxx/Script/DailyChk/chk_path_full.ksh PRODB 2>&1 >/opt/app/oracle/Script/DailyLog/chk_path_full.log 
如果要求指令碼在指定的時間段，比如只在每天晚上的11:30執行，就可以寫成下面的形式。
從配置來看，job是每隔半個小時執行一次，而且所做的檢查工作也不復雜，執行時間應該會很短。配置中這個job已經被禁用，如果我們能夠證明這個job是透過crontab執行的就能夠說明是操作問題。因為crontab裡面已經禁用，但是實際上job還在執行。
透過程式的資訊，我們知道這個程式已經執行了近2021分鐘，我們來推算一下執行的時間。2021/60=33個小時，從下午3點往前推33個小時，就是在29號早晨的7點左右開始執行的。
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                                                       
25807 oraccbs1  25   0  8728  732  564 R 100.0  0.0   2021:19 /bin/sh -c /opt/app/oracle/xxxxxx/Script/DailyChk/chk_path_full.ksh PRODB 2>&1 >/opt/app/oracle/Script/DailyLog/chk_path_full.log 

這個時候日誌就是最好的證明工具，可以在/var/spool/mail/oraccbs1下面找到相應的日誌。
日誌中最近的一次執行時間是在昨天的早晨7:30,之後就沒有任何相關的日誌了。
Mon Dec 29 07:30:01 2014
Return-Path: <oraccbs1@localhost.localdomain>
Received: from localhost.localdomain (xxxxx[127.0.0.1])
        by localhost.localdomain (8.13.8/8.13.8) with ESMTP id sBT0U1mr013412
        for <oraccbs1@localhost.localdomain>; Mon, 29 Dec 2014 07:30:01 +0700
Received: (from oraccbs1@localhost)
        by localhost.localdomain (8.13.8/8.13.8/Submit) id sBT0U1Jh013347;
        Mon, 29 Dec 2014 07:30:01 +0700
Date: Mon, 29 Dec 2014 07:30:01 +0700
Message-Id: <201412290030.sBT0U1Jh013347@localhost.localdomain>
From: root@localhost.localdomain (Cron Daemon)
To: oraccbs1@localhost.localdomain
Subject: Cron <oraccbs1@xxxxxx>  /opt/app/oracle/xxxxxx/Script/DailyChk/chk_path_full.ksh PRODB 2>&1 >/opt/app/oracle/Script/DailyLog/chk_path_full.log
Content-Type: text/plain; charset=UTF-8
Auto-Submitted: auto-generated

/bin/sh: fork: Resource temporarily unavailable

From oraccbs1@localhost.localdomain  Mon Dec 29 07:30:05 2014
。。。。
得到了這些基本資訊，就能夠基本確定問題了。
至於crontab的修改，可以使用crontab -e來完成。感覺就跟vi操作一樣。客戶做了確認之後，手工kill掉了那個job,那個問題就解決了。
有很多朋友反饋說為什麼會導致CPU異常，因為問題已經修復了，我就從支離破碎的日誌中做了簡單的分析。
可以透過上面的日誌看到fork: Resource temporarily unavailable這個問題，說明在執行crontab job的時候發生了問題，這個問題可能是資料庫中其它的資源消耗導致的，也可能是傳送訊息的環節導致的，因為傳送訊息的細節是客戶來維護，他們不願意透露更多的細節，我們只能做主觀上的猜測了。
不過透過下面的日誌能夠得到一些資訊。就是crontab的job很可能是個殭屍程式。存在兩個相同的程式。
>ps -ef|grep DailyChk

oraccbs1 14187  7786  0 14:59 pts/10   00:00:00 grep DailyChk

oraccbs1 25793     1  0 Dec29 ?        00:00:00 /bin/sh -c /opt/app/oracle/xxxxxx/Script/DailyChk/chk_path_full.ksh PRODB 2>&1 >/opt/app/oracle/Script/DailyLog/chk_path_full.log

oraccbs1 25807 25793 99 Dec29 ?        1-09:58:51 /bin/sh -c /opt/app/oracle/xxxxxx/Script/DailyChk/chk_path_full.ksh PRODB 2>&1 >/opt/app/oracle/Script/DailyLog/chk_path_full.log

最後從昨天的top截圖中發現瞭如下的內容，可以基本斷定問題是crontab 的那個job成為了殭屍程式導致的。
Tasks: 7196 total,  26 running, 7165 sleeping,   0 stopped,   5 zombie
Cpu(s):  7.8%us,  1.5%sy,  0.0%ni, 90.1%id,  0.1%wa,  0.1%hi,  0.4%si,  0.0%st
Mem:  363033360k total, 116349772k used, 246683588k free,  2176616k buffers