從 GAE 的 log 觀察伺服器回應是否正常

這幾天為了 GAE 的 cron job 老是沒能成功地在 15:00 從 PHP 應用程式擷取報告而苦惱, 原先懷疑 GAE 的 cron 是否有問題, 但檢查 log 都有正常 trigger, 後來又懷疑是網頁被 cache 了, 但經過調整 meta 為 nocache 還是無效, 每天 15:00 那一筆 cron_log 就是會 miss 掉, 連帶影響 15:10 的 create_daily_report 與 15:15 的 fetch_daily_report.
昨晚比對舊網站資料, 測試了一番也是徒勞無功, 於是仔細檢查 GAE 的 Logs, 再比對我的 cron_log 資料表, 發現很有可能是 PHP 主機問題, 因為我發現不只 fetch_twse_daily_close 會有 miss 現象, 而是所有程式隨機性的都有 miss 現象, 也就是說, GAE 的 cron 都很忠實地產生 trigger, 但 PHP 主機可能出問題 (DOWN), 導致 PHP 應用程式執行失敗, 所以 cron_log 資料表就不會記錄執行結果.
去看 GAE 的 Logs 便能找出端睨, 例如執行成功的 Logs 回應紀錄如下 :

2013-07-09 17:11:14.469 /fetch_yahoo_dividend 200 34936ms 2kb AppEngine-Google; (+http://code.google.com/appengine)0.1.0.1 - - [09/Jul/2013:17:11:14 -0700] "GET /fetch_yahoo_dividend HTTP/1.1" 200 2961 - "AppEngine-Google; (+http://code.google.com/appengine)" "twstockbot.appspot.com" ms=34937 cpu_ms=0 cpm_usd=0.000351 queue_name=__cron task_name=174a7b46e620a5733ceebdfa6942bc20 app_engine_release=1.8.1 instance=00c61b117c99b5aaefeb1058c41861042bf0ce30

而執行失敗的 Logs 回應紀錄觀察到有兩種, 第一種雖然回應 200, 但是實際上 PHP 程式並未正常執行完畢 :

2013-07-09 16:39:11.898 /fetch_2330_tw_basic 200 2792ms 0kb AppEngine-Google; (+http://code.google.com/appengine)0.1.0.1 - - [09/Jul/2013:16:39:11 -0700] "GET /fetch_2330_tw_basic HTTP/1.1" 200 85 - "AppEngine-Google; (+http://code.google.com/appengine)" "twstockbot.appspot.com" ms=2792 cpu_ms=0 cpm_usd=0.000049 queue_name=__cron task_name=7fccf1fc3674ba5c904a796665b90e9f app_engine_release=1.8.1 instance=00c61b117c99b5aaefeb1058c41861042bf0ce30

第二種失敗例子就是回應 500 (伺服器內部錯誤) :

2013-07-09 16:15:08.646 /fetch_2330_tw_basic 500 3051ms 2kb AppEngine-Google; (+http://code.google.com/appengine)0.1.0.1 - - [09/Jul/2013:16:15:08 -0700] "GET /fetch_2330_tw_basic HTTP/1.1" 500 2313 - "AppEngine-Google; (+http://code.google.com/appengine)" "twstockbot.appspot.com" ms=3051 cpu_ms=0 cpm_usd=0.000264 queue_name=__cron task_name=7fccf1fc3674ba5c904a796665b90e9f app_engine_release=1.8.1 instance=00c61b117c99b5aaefeb1058c41861042bf0ce30

其他觀察結果摘要如下 :

200 34936ms 2kb ms=34937 cpu_ms=0 cpm_usd=0.000351  OK
200 1708ms 0kb ms=1708 cpu_ms=0 cpm_usd=0.000115 OK
200 2792ms 0kb ms=2792 cpu_ms=0 cpm_usd=0.00004 NG
200 192ms 0kb ms=192 cpu_ms=22 cpm_usd=0.000031 NG
200 2792ms 0kb ms=2792 cpu_ms=0 cpm_usd=0.000049 NG
200 88ms 0kb  ms=88 cpu_ms=0 cpm_usd=0.000031 NG
500 3051ms 2kb ms=3051 cpu_ms=0 cpm_usd=0.000264 NG
200 275ms 0kb ms=275 cpu_ms=0 cpm_usd=0.000029 NG
200 87ms 0kb ms=88 cpu_ms=0 cpm_usd=0.000031 NG
200 1821ms 0kb ms=1821 cpu_ms=0 cpm_usd=0.000115 OK
200 101ms 0kb ms=101 cpu_ms=22 cpm_usd=0.000031 NG

歸納上面結果可知, 觀察重點在於三個 : 回應碼 (200?), 資料量 (0KB?), 以及 cpm_used, 因為每一個應用程式都會吐出資料 (我的都是 1, 2KB), 所以不應該 0KB, 如果不是 0KB, 而且 cpm_used>0.000100, 那麼就是成功的; 否則就是失敗的. 若回應 200 且資料量為 2KB, 最後的觀察關鍵在 cpm_used, 失敗的範例通常都是 0.000031, 最大有 0.000049, 沒看到有大於 0.000100 的失敗例子.

我想這就是免費主機的特徵, 也就是他不保證 99.9% 的穩定性, 偶而會 DOWN 個半小時一小時的, 或許只有 80% 也說不定. 解決之道就是用人海戰術, GAE 的 Cron 不要用指定時間 (every day 15:00), 要改成週期性的 every 1 hours 或 every 60 minutes.

以下這一篇是關於 GAE log 的解密, 值得參考 :
Demystifying the App Engine request logs