grep 零寬斷言

• 原文連結
• 參考
• 參考二

 

算是正則環視的一個簡單應用吧。

http://pengqi.me/2011/05/%E4%BD%BF%E7%94%A8grep%E5%92%8C%E6%AD%A3%E5%88%99%E6%9D%A5%E5%88%86%E6%9E%90web%E6%9C%8D%E5%8A%A1%E5%99%A8%E6%97%A5%E5%BF%97/

前兩天因為第三方遊戲伺服器掉線，導致大量使用者同時登入我的伺服器，將伺服器負載瞬間提高到200+，如此恐怖的數字讓我不得不考慮增加伺服器來抵抗問題重現，然而我的伺服器平時負載都很低，0.1都不到，增加伺服器來應付這樣短暫的風暴未免太過於浪費，於是我決定從日誌下手，找到我的網站的瓶頸，希望能通過改善程式來解決這個問題。

第一步，定位時間

我的記錄檔裡包含了最近一個禮拜的資料，然而我需要的只是風暴發生時產生的資料，總共不超過20分鐘，怎麼取呢？因為我的Web伺服器採用的是標準的combined格式

$remote_addr - $remote_user [$time_local] "$request"$status $body_bytes_sent "$http_referer" "$http_user_agent"

而且全部是PHP動態請求，所以我決定從time_local下手，找到並發訪問量最高的時間段，這很容易辦到：

grep -oP '12\/May\/2011(:\d{2}){3}' access.log | uniq -c | sort -n > time.sort

得到如下結果（部分）

從18點43分開始，我的伺服器每秒需要響應120多次動態請求，而18:46:49秒更加變態，211次！看來把我伺服器拖垮的，就是18點43分到18點50分這一段。

第二步， 過濾指令碼

定位好了時間，現在要做的，就是取出這一時間段的日誌再做分析，使用以下指令碼將18:43分到18:50分之間的日誌取出來

grep -P '12\/May\/2011:18:4[3-9]:\d{2}' access.log > storm.log第三步， 找出元兇

得到了storm.log，下面我便要找出拖垮我伺服器的元兇，及訪問數量最高的$request。因為$request都是 “GET /***** HTTP/1.1″ 或 “POST /****” 這樣的格式， 所以可以通過簡單的正則取出$request，如下

grep -oP '((?<=GET\s)|(?<=POST\s))[^?\s]+' storm.log | sort \ | uniq -c | sort -n > request.sort

(?<=GET\s)這個正則叫作零寬斷言，是將要被匹配文字前面的條件，即除非前面有’GET ‘出現，後面的才匹配。
上面的指令碼得到以下結果：

從這張圖我們便可以找出程式方面的瓶頸了，因為上面這些請求大部分都是ajax請求，所以明顯的，像’users/getuser’、’games/getservers/sxd’這樣的資料請求完全可以被瀏覽器緩衝起來，而’users/logoutService’根據我們的商務邏輯也顯得毫無必要，將這三項請求砍掉能節省將近60%的資源！
以下便是通過最佳化程式碼後13號應對的又一次風暴結果。

看到沒，’/users/getuser’請求減少了將近一半，而’/games/getserver/sxd’則減少了近75%，總量減少了近40%！然而’/users/logoutService’卻不盡如人意，只少了三成，我們待會再尋找其原因。

通過以上程式的最佳化和一些系統配置的調整，這次風暴只將我的伺服器負載升高到了10+，並在十幾秒後就很快地平穩了下來，和前一天的200+相比，可以說成功地解決了短暫風暴的問題。

第四步，找出來源

上一步遺留了一個問題，即我明明最佳化了程式，去掉了不必要的’users/logoutService’，為何在風暴中，它依然出現了那麼多次，所以我決定分析$http_referer，找出這些請求都是從哪來的。
根據日誌的格式，$http_referer前面都有一個$body_bytes_sent、一個空格和一個雙引號，例如

27.37.113.145 - - [14/May/2011:22:30:47 +0800] "GET /users/logoutService HTTP/1.1" 200 431 "http://sxd.xd.com/" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"

因為$body_bytes_sent始終是個數字，這樣就可以通過以下正則來找出來源

grep -P '\/users\/logoutService?' storm.log \ | grep -oP '(?<=\d\s")[^?"]+' | sort | uniq -c | sort -n > logout.referer.sort

先過濾出logout的日誌，再通過零寬斷言找出來源。得到的結果出乎我意料，來自於一個我在上一步中已經調整過的頁面，明明去掉了不必要的’users/logoutService’請求，為何還會重複出現？仔細觀察代碼後並沒發現可疑的地方，於是推測是CDN緩衝的問題，這些使用者用的JS版本可能還是前一天的，清理緩衝，加上版本號碼，期待下次風暴來驗證這一推論！