日志分析在web系統(tǒng)中故障排查、性能分析方面有著非常重要的作用

日志分析在web系統(tǒng)中故障排查、性能分析方面有著非常重要的作用。該工具的側重點不是通常的PV，UV等展示，而是在指定時間段內(nèi)提供細粒度（最小分鐘級別，即一分鐘內(nèi)的日志做抽象和匯總）的異常定位和性能分析。

環(huán)境安裝

Python 3.4+

pymongo 3.4.0+

MongoDB server

先明確幾個術語

uri指請求中不包含參數(shù)的部分；request_uri指原始的請求，包含參數(shù)或者無參數(shù)；args指請求中的參數(shù)部分。（參照nginx中的定義）uri_abs和args_abs是指對uri和args進行抽象處理后的字符串（以便分類），例如："/sub/0/100414/4070?channel=ios&version=1.4.5"經(jīng)抽象處理轉換為uri_abs:"/sub/*/*/*"，args_abs:"channel=*&version=*"

特點

提供一個日志分析的總入口：經(jīng)由此入口，可查看某站點所有 server 產(chǎn)生日志的匯總分析；亦可根據(jù)時間段和server兩個維度進行過濾

支持對 requesturi，IP 和 responsecode 進行分析，基于請求數(shù)、響應大小、響應時間三個大維度進行分析；另外不同子項又各有特點

（核心思想）以某一類uri 或其對應的各類args 為維度進行分析，即對 requesturi 進行抽象處理將其分為 uriabs 和 args_abs 兩部分

3中提到的抽象歸類思想，默認抽象方法可滿足大部分需求；另外也提供了定制抽象規(guī)則的選項，基于此可靈活指定請求中的任何部分是否要抽象處理

requesturi 分析能直觀展示哪類請求數(shù)量多、哪類請求耗時多、哪類請求占流量；另外可展示某一類請求在不同粒度里(minute, tenmin, hour, day)各指標隨時間的分布變化；也可以針對某一 uriabs 分析其不同 argsabs 各指標的分布

IP 分析將所有請求分為3種來源(fromcdn/proxy, fromreverseproxy, fromclientdirectly)，三種來源各自展示其訪問量前 N 的 IP 地址；并且可展示某一 IP 訪問的各指標隨時間的分布；也可針對某一 IP 分析其產(chǎn)生的不同 uriabs 各指標的分布

通過4分位數(shù)概念以實現(xiàn)對響應時間和響應大小更準確的描述，因為對于日志中的響應時間，算數(shù)平均值的參考意義不大

高性能：本著誰產(chǎn)生的日志誰處理的思想，日志分析腳本loganalyse要在web服務器上定時運行，因而loganalyse的高效率低資源也是重中之重。經(jīng)測試，在筆者的服務器上（磁盤：3*7200rpm組RAID5，千兆局域網(wǎng)），對于不同的日志文件，處理速度在20000行/s~30000行/s之間

實現(xiàn)思路

分析腳本（log_analyse.py）部署到各臺 web server，并通過 crontab 設置定時運行。log_analyse.py利用python的re模塊通過正則表達式對日志進行分析處理，取得uri、args、時間當前、狀態(tài)碼、響應大小、響應時間、server name等信息并進行初步加工然后存儲進MongoDB。查看腳本（log_show.py）作為入口即可對所有web server的日志進行分析查看，至于實時性，取決于web server上log_analyse.py腳本的執(zhí)行頻率。

前提規(guī)范

各臺server的日志文件按統(tǒng)一路徑存放

日志格式、日志命名規(guī)則保持一致(代碼中規(guī)定格式為xxx.access.log)

每天的0點日志切割

日志格式?jīng)Q定了代碼中的正則表達式，是可根據(jù)自己情況參考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 日志，按照如上原則，稍作就可以使用該工具分析處理。

對于異常日志的處理

如果想靠空格或雙引號來分割各段的話，主要問題是面對各種不規(guī)范的記錄時(原因不一而足，而且也是樣式繁多)，無法做到將各種異常都考慮在內(nèi)，所以項目中采用了re模塊而不是簡單的split()函數(shù)的原因。代碼里對一些“可以容忍”的異常記錄通過一些判斷邏輯予以處理；對于“無法容忍”的異常記錄則返回空字符串并將日志記錄于文件。其實對于上述的這些不規(guī)范的請求，最好的辦法是在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 Showthis screen.

-f --from Start time.Format:%y%m%d[%H[%M]],%H and%M is optional

-t --to End time.Formatis same as--from

-l --limit Number of lines in output,0 means no limit.[default:5]

-s --server Web server hostname

-g --group_by Groupby 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.

Periodis 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參數(shù)對起始時間和指定server進行過濾

request子命令

對指定站點今日已入庫的數(shù)據(jù)進行分析

[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/*/*

通過上例可觀察指定時間內(nèi)（默認當天0時至當前時間）hits/bytes/time三個維度的排名以及響應時間和響應大小的分布情況。例如，看到某個uriabs只有比較少的hits確產(chǎn)生了比較大的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，F(xiàn)romreverseproxy，F(xiàn)romclient_directly，然后各自分類內(nèi)按請求次數(shù)對IP地址進行排序

distribution 子命令

對 “所有request” 或 “指定uri/request_uri” 按 “分/十分/時/天” 為粒度進行聚合統(tǒng)計

對 “指定IP” 按 “分/十分/時/天” 為粒度進行聚合統(tǒng)計

適用場景：查看request/IP隨時間在各聚合粒度內(nèi)各項指標的變化情況，例如針對某個uri發(fā)現(xiàn)其請求數(shù)（或帶寬）變大，則可通過distribution子命令觀察是某一段時間突然變大呢，還是比較平穩(wěn)的變大

# 示例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"在指定時間段內(nèi)的分布情況，包括hits/bytes/time總量以及每個粒度內(nèi)個指標相對于總量的占比；該子命令亦能展示各指標隨時間的“趨勢”。

說明： minute字段為指定的聚合（group）粒度，1803091654 表示“18年03月09日16時54分”可通過-g參數(shù)指定聚合的粒度（minute/tenmin/hour/day）distribution子命令后可以跟具體的uri/requesturi（顯示該uri/request_uri以指定粒度隨時間的分布）或不跟uri（顯示所有請求以指定粒度隨時間的分布）

# 示例2: 分析指定IP產(chǎn)生的請求數(shù)/帶寬隨時間分布情況, 默認聚合粒度為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 表示不限制輸出行數(shù)（即輸出所有結果）

detail 子命令：

對某一uri進行詳細分析，查看其不同參數(shù)（args）的各項指標分布

對某一IP進行詳細分析，查看其產(chǎn)生的請求在不同uri_abs間的分布情

適用場景：比如定位到某一類型的uriabs在某方面（hits/bytes/time）有異常，就可以通過detail子命令對該類uriabs進行更近一步的分析，精確定位到是哪種參數(shù)（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所對應的不同參數(shù)各個指標的情況。另外還有一個附帶的發(fā)現(xiàn)：開發(fā)在書寫參數(shù)時相同的參數(shù)組合沒有按同一個順序書寫，雖不影響功能，但在精準的進行應用性能監(jiān)控的時候會造成一定困擾。

說明：detail子命令后跟隨uri（不含參數(shù)，含參數(shù)的話將忽略參數(shù)）

# 示例2: 觀察某個IP分別產(chǎn)生了多少種請求, 每種請求的(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分鐘，自定義）執(zhí)行，在需要時通過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進行抽象化（抽象出特定的請求模式，即將請求分類看待）處理之后的結果，默認規(guī)則如下uri：將request_uri以"/"和"."分割為幾段，若某一段全部由數(shù)字組成則將其抽象為一個"*" args：將所有的value替換成"*"

common/common.py中還有一些其他有趣的函數(shù)