來源:Python中文社群
ID:python-china
日誌分析
日誌分析在web系統中故障排查、效能分析方面有著非常重要的作用。該工具的側重點不是通常的PV,UV等展示,而是在指定時間段內提供細粒度(最小分鐘級別,即一分鐘內的日誌做抽象和彙總)的異常定位和效能分析。
環境安裝
-
Python 3.4+
-
pymongo 3.4.0+
-
MongoDB server
先明確幾個術語
uri
指請求中不包含引數的部分; request_uri
指原始的請求,包含引數或者無引數; args
指請求中的引數部分。(參照nginx中的定義)uri_abs
和 args_abs
是指對uri和args進行抽象處理後的字串(以便分類),例如:"/sub/0/100414/4070?channel=ios&version;=1.4.5"
經抽象處理轉換為 uri_abs:
“/sub/*/*/*”, args_abs:
“channel=*&version;=*”
特點
-
提供一個日誌分析的總入口:經由此入口,可檢視某站點所有 server 產生日誌的彙總分析;亦可根據
時間段
和server
兩個維度進行過濾 -
支援對 requesturi,IP 和 responsecode 進行分析,基於
請求數
、響應大小
、響應時間
三個大維度進行分析;另外不同子項又各有特點 -
(核心思想)以某一類 uri 或其對應的各類 args 為維度進行分析,即對 requesturi 進行抽象處理將其分為 uriabs 和 args_abs 兩部分
-
3中提到的抽象歸類思想,預設抽象方法可滿足大部分需求;另外也提供了定製抽象規則的選項,基於此可靈活指定請求中的任何部分是否要抽象處理
-
requesturi 分析能直觀展示哪類請求數量多、哪類請求耗時多、哪類請求佔流量;另外可展示某一類請求在不同粒度裡(minute, tenmin, hour, day)各指標隨時間的分佈變化;也可以針對某一 uriabs 分析其不同 argsabs 各指標的分佈
-
IP 分析將所有請求分為3種來源(fromcdn/proxy, fromreverseproxy, fromclientdirectly),三種來源各自展示其訪問量前 N 的 IP 地址;並且可展示某一 IP 訪問的各指標隨時間的分佈;也可針對某一 IP 分析其產生的不同 uriabs 各指標的分佈
-
透過4分位數概念以實現對
響應時間
和響應大小
更準確的描述,因為對於日誌中的響應時間,算數平均值的參考意義不大 -
高效能:本著誰產生的日誌誰處理的思想,日誌分析指令碼loganalyse要在web伺服器上定時執行,因而loganalyse的高效率低資源也是重中之重。經測試,在筆者的伺服器上(磁碟:3*7200rpm組RAID5,千兆區域網),對於不同的日誌檔案,處理速度在20000行/s~30000行/s之間
實現思路
分析指令碼( log_analyse.py
)部署到各臺 web server,並透過 crontab 設定定時執行。 log_analyse.py
利用python的re模組透過正則運算式對日誌進行分析處理,取得 uri
、 args
、 時間當前
、 狀態碼
、 響應大小
、 響應時間
、 server name
等資訊併進行初步加工然後儲存進MongoDB。檢視指令碼( log_show.py
)作為入口即可對所有web server的日誌進行分析檢視,至於實時性,取決於web server上 log_analyse.py
指令碼的執行頻率。
前提規範
-
各臺server的日誌檔案按統一路徑存放
-
日誌格式、日誌命名規則保持一致(程式碼中規定格式為xxx.access.log)
-
每天的0點日誌切割
日誌格式決定了程式碼中的正則運算式,是可根據自己情況參考 analyse_config.py
中的正則定義進行定製的)。專案中預定義的日誌格式對應如下:
log_format access '$remote_addr - [$time_local] "$request" '
'$status $body_bytes_sent $request_time "$http_referer" '
'"$http_user_agent" - $http_x_forwarded_for';
對於其他格式的 nginx 日誌或者 Apache 日誌,按照如上原則,稍作就可以使用該工具分析處理。
對於異常日誌的處理
如果想靠空格或雙引號來分割各段的話,主要問題是面對各種不規範的記錄時(原因不一而足,而且也是樣式繁多),無法做到將各種異常都考慮在內,所以專案中採用了 re
模組而不是簡單的 split()
函式的原因。程式碼裡對一些“可以容忍”的異常記錄透過一些判斷邏輯予以處理;對於“無法容忍”的異常記錄則傳回空字串並將日誌記錄於檔案。
其實對於上述的這些不規範的請求,最好的辦法是在nginx中定義日誌格式時,用一個特殊字元作為分隔符,例如“|”。這樣就不需要re模組,直接字串分割就能正確的獲取到各段(效能會好些)。
log_show.py使用說明:
幫助資訊
[ljk@demo ~]$ log_show --help
Usage:
log_show
[options] request [distribution [ ]|detail ]
log_show
[options] ip [distribution |detail ]
log_show
[options] error [distribution |detail ]
Options:
-h --help Show this screen.
-f --from
Start time. Format: %y%m%d[%H[%M]], %H and %M is optional
-t --to
End time. Format is same as --from
-l --limit
Number of lines in output, 0 means no limit. [default: 5]
-s --server
Web server hostname
-g --group_by
Group by every minute, every ten minutes, every hour or every day,
valid values: "minute", "ten_min", "hour", "day". [default: hour]
distribution Show distribution(about hits,bytes,time,etc) of:
all or specific 'request', the specific 'ip', the specific 'error_code' in every period.
Period is specific by --group_by
detail Show details of:
detail 'args' analyse of the specific 'uri'(if it has args);
detail 'uri' analyse of the specific 'ip' or 'error_code'
Notice: it's best to put 'request_uri', 'uri' and 'ip' in quotation marks.
所有示例均可透過 -f
, -t
, -s
引數對 起始時間
和 指定server
進行過濾
request子命令
對指定站點今日已入庫的資料進行分析
[ljk@demo ~]$ log_show api request -l 3
====================
Total_hits:999205 invalid_hits:581
====================
hits percent time_distribution(s) bytes_distribution(B) uri_abs
430210 43.06% %25<0.01 %50<0.03 %75<0.06 %100<2.82 %25<42 %50<61 %75<63 %100<155 /api/record/getR
183367 18.35% %25<0.02 %50<0.03 %75<0.06 %100<1.73 %25<34 %50<196 %75<221 %100<344 /api/getR/com/*/*/*
102299 10.24% %25<0.02 %50<0.02 %75<0.05 %100<1.77 %25<3263 %50<3862 %75<3982 %100<4512 /view/*/*/*/*.js
====================
Total_bytes:1.91 GB
====================
bytes percent time_distribution(s) bytes_distribution(B) uri_abs
1.23 GB 64.61% %25<0.03 %50<0.04 %75<0.1 %100<1.96 %25<2549 %50<17296 %75<31054 %100<691666 /api/NewCom/list
319.05 MB 16.32% %25<0.02 %50<0.02 %75<0.05 %100<1.77 %25<3263 %50<3862 %75<3982 %100<4512 /view/*/*/*/*.js
167.12 MB 8.55% %25<0.15 %50<0.19 %75<0.55 %100<2.93 %25<2791 %50<3078 %75<3213 %100<11327 /api/getR/com/*/*
====================
Total_time:117048s
====================
cum. time percent time_distribution(s) bytes_distribution(B) uri_abs
38747 33.10% %25<0.01 %50<0.03 %75<0.06 %100<2.82 %25<42 %50<61 %75<63 %100<155 /api/record/getR
22092 18.87% %25<0.02 %50<0.03 %75<0.06 %100<1.73 %25<34 %50<196 %75<221 %100<344 /api/getR/com/*/*/*
17959 15.34% %25<0.15 %50<0.19 %75<0.55 %100<2.93 %25<2791 %50<3078 %75<3213 %100<11327 /api/getRInfo/com/*/*
透過上例可觀察指定時間內(預設當天0時至當前時間)hits/bytes/time三個維度的排名以及響應時間和響應大小的分佈情況。例如,看到某個uriabs只有比較少的hits確產生了比較大的bytes或耗費了較多的time,那麼該uriabs是否值得關註一下呢。
ip子命令
顯示基於ip地址的分析結果
[ljk@demo ~]$ log_show.py api ip -l 2
====================
From_cdn/Proxy: hits hits(%) bytes bytes(%) time(%)
==================== 199870 99.94 570.51 MB 99.99 99.99
Last_cdn_ip
xxx.57.xxx.189 1914 0.96 696.18 KB 0.12 0.68
xxx.206.xxx.154 1741 0.87 1.56 MB 0.27 0.98
User_ip_via_cdn
xxx.249.xxx.56 787 0.39 154.82 KB 0.03 0.23
xxx.60.xxx.86 183 0.09 1.05 MB 0.18 0.13
====================
From_reverse_proxy: hits hits(%) bytes bytes(%) time(%)
==================== 66 0.03 68.83 KB 0.01 0.01
User_ip_via_proxy
xxx.188.xxx.21 2 0.00 1.53 KB 0.00 0.00
xxx.5.xxx.4 2 0.00 324.00 B 0.00 0.00
====================
From_client_directly: hits hits(%) bytes bytes(%) time(%)
==================== 64 0.03 8.32 KB 0.00 0.00
Remote_addr
192.168.1.202 29 0.01 58.00 B 0.00 0.00
192.168.1.200 29 0.01 58.00 B 0.00 0.00
IP分析的思想是將請求按來源歸為三大類:Fromcdn/Proxy,Fromreverseproxy,Fromclient_directly,然後各自分類內按請求次數對IP地址進行排序
distribution 子命令
-
對 “所有request” 或 “指定uri/request_uri” 按 “分/十分/時/天” 為粒度進行聚合統計
-
對 “指定IP” 按 “分/十分/時/天” 為粒度進行聚合統計
適用場景:檢視request/IP隨時間在各聚合粒度內各項指標的變化情況,例如針對某個uri發現其請求數(或頻寬)變大,則可透過 distribution
子命令觀察是某一段時間突然變大呢,還是比較平穩的變大
# 示例1: 分析指定request的分佈情況, 指定按minute進行分組聚合, 預設顯示5行
[ljk@demo ~]$ python log_show.py api request distribution "/view/*/*.json" -g minute
====================
uri_abs: /view/*/*.json
Total_hits: 17130 Total_bytes: 23.92 MB
====================
minute hits hits(%) bytes bytes(%) time_distribution(s) bytes_distribution(B)
1803091654 1543 9.01% 2.15 MB 8.98% %25<0.03 %50<0.03 %75<0.05 %100<1.07 %25<1532 %50<1593 %75<1645 %100<1982
1803091655 1527 8.91% 2.13 MB 8.88% %25<0.03 %50<0.04 %75<0.05 %100<1.04 %25<1538 %50<1592 %75<1642 %100<2143
1803091656 1464 8.55% 2.05 MB 8.57% %25<0.03 %50<0.04 %75<0.05 %100<1.03 %25<1536 %50<1592 %75<1642 %100<1952
1803091657 1551 9.05% 2.15 MB 8.97% %25<0.02 %50<0.03 %75<0.04 %100<0.89 %25<1534 %50<1594 %75<1639 %100<1977
1803091658 1458 8.51% 2.06 MB 8.61% %25<0.02 %50<0.03 %75<0.04 %100<2.35 %25<1540 %50<1596 %75<1644 %100<2146
透過上例,可展示"/view/*/*.json"在指定時間段內的分佈情況,包括hits/bytes/time總量以及每個粒度內個指標相對於總量的佔比;該子命令亦能展示各指標隨時間的“趨勢”。
說明: minute欄位為指定的聚合(group)粒度,1803091654 表示“18年03月09日16時54分”
可透過 -g
引數指定聚合的粒度(minute/tenmin/hour/day)distribution
子命令後可以跟具體的uri/requesturi(顯示該uri/request_uri以指定粒度隨時間的分佈)或不跟uri(顯示所有請求以指定粒度隨時間的分佈)
# 示例2: 分析指定IP產生的請求數/頻寬隨時間分佈情況, 預設聚合粒度為hour
[ljk@demo ~]$ python log_show.py api ip -t 180314 distribution "140.206.109.174" -l 0
====================
IP: 140.206.109.174
Total_hits: 10999 Total_bytes: 4.83 MB
====================
hour hits hits(%) bytes bytes(%)
18031306 1273 11.57% 765.40 KB 15.47%
18031307 2133 19.39% 1004.74 KB 20.31%
18031308 2211 20.10% 1.00 MB 20.74%
18031309 2334 21.22% 1.05 MB 21.72%
18031310 2421 22.01% 850.79 KB 17.20%
18031311 627 5.70% 226.30 KB 4.57%
說明: hour欄位表示預設的聚合粒度,18031306表示“18年03月13日06時”
-l 0 表示不限制輸出行數(即輸出所有結果)
detail 子命令:
-
對某一uri進行詳細分析,檢視其不同引數(args)的各項指標分佈
-
對某一IP進行詳細分析,檢視其產生的請求在不同uri_abs間的分佈情
適用場景:比如定位到某一型別的uriabs在某方面(hits/bytes/time)有異常,就可以透過detail子命令對該類uriabs進行更近一步的分析,精確定位到是哪種引數(args_abs)導致的異常;或者觀察到某個IP訪問異常,可以再深入一下該IP是泛泛的訪問呢,還是隻對某些uri感興趣。
# 示例1:
[ljk@demo ~]$ python log_show.py api -f 180201 request detail "/recommend/update" -l 3
====================
uri_abs: /recommend/batchUpdate
Total_hits: 10069 Total_bytes: 7.62 MB
====================
hits hits(%) bytes bytes(%) time(%) time_distribution(s) bytes_distribution(B) args_abs
4568 45.37% 3.46 MB 45.44% 47.96% %25<0.04 %50<0.06 %75<0.07 %100<0.47 %25<755 %50<795 %75<845 %100<1484 uid=*&category;_id=*&channel;=*&version;=*
4333 43.03% 3.25 MB 42.64% 42.30% %25<0.03 %50<0.05 %75<0.07 %100<0.48 %25<752 %50<791 %75<840 %100<1447 category_id=*&channel;=*&uid;=*&version;=*
389 3.86% 314.15 KB 4.03% 0.88% %25<0.02 %50<0.03 %75<0.04 %100<0.06 %25<766 %50<802 %75<850 %100<1203 category_id=*&channel;=*&version;=*
透過上例可觀察到"/recommend/update"這個uri所對應的不同引數各個指標的情況。另外還有一個附帶的發現:開發在書寫引數時相同的引陣列合沒有按同一個順序書寫,雖不影響功能,但在精準的進行應用效能監控的時候會造成一定困擾。
說明: detail
子命令後跟隨uri(不含引數,含引數的話將忽略引數)
# 示例2: 觀察某個IP分別產生了多少種請求, 每種請求的(hits/bytes/time)指標
[ljk@demo ~]$ python log_show.py m -t 180314 ip detail "1.2.3.4"
====================
IP: 140.206.109.174
Total_hits: 10999 Total_bytes: 4.83 MB
====================
hits hits(%) bytes bytes(%) time(%) uri_abs
10536 95.79% 405.47 KB 8.19% 92.01% /introduction/watch
147 1.34% 1.90 MB 39.31% 1.93% /view/*/*.html
138 1.25% 407.42 KB 8.23% 2.41% /chapinfo/*/*.html
42 0.38% 644.88 KB 13.03% 1.38% /info/*.html
30 0.27% 229.98 KB 4.65% 1.14% /classify/*.json
loganalyse.py部署說明: 該指令碼的設計標的是將其放到web server的的計劃任務裡,定時(例如每30分鐘或10分鐘,自定義)執行,在需要時透過logshow.py進行分析即可。
*/15 * * * * export LANG=zh_CN.UTF-8;python3 /home/ljk/log_analyse.py &> /tmp/log_analyse.log
Note
-
其中
uri_abs
和args_abs
是對uri和args進行抽象化(抽象出特定的請求樣式,即將請求分類看待)處理之後的結果,預設規則如下
uri:將request_uri以"/"和"."分割為幾段,若某一段全部由數字組成則將其抽象為一個"*"
args:將所有的value替換成"*" -
common/common.py
中還有一些其他有趣的函式
本文作者
jkklee,6年運維老司機一枚,擅長複雜場景下的故障排查,效能最佳化。目前比較側重於將自己這些年的運維積累轉化成通用易用的各種工具,希望能幫到更多的運維同胞。
本文專案GitHub地址,歡迎star和fork:
https://github.com/jkklee/web_log_analyse
《Python人工智慧和全棧開發》2018年07月23日即將在北京開課,120天衝擊Python年薪30萬,改變速約~~~~
*宣告:推送內容及圖片來源於網路,部分內容會有所改動,版權歸原作者所有,如來源資訊有誤或侵犯權益,請聯絡我們刪除或授權事宜。
- END -
更多Python好文請點選【閱讀原文】哦
↓↓↓