性能工具之linux常見日誌統計分析命令

2021 年 6 月 25 日
筆記
linux

引言

我前幾天寫過的性能工具之linux三劍客awk、grep、sed詳解，我們已經詳細介紹 linux 三劍客的基本使用，接下來我們看看具體在性能測試領域的運用，本文主要介紹的是在 Tomcat 和 Nginx access日誌的統計分析。

Tomcat統計請求響應時間

server.xml 使用配置方式，%D-請求時間，%F響應時間

<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
prefix="localhost_access_log." suffix=".txt"
pattern="%h %l %u [%{yyyy-MM-dd HH:mm:ss}t] %{X-Real_IP}i "%r" %s %b %D %F" />

欄位說明如下：

%h – 發起請求的客戶端 IP 地址。這裡記錄的 IP 地址並不一定是真實用戶客戶機的 IP 地址，它可能是私網客戶端的公網映射地址或代理伺服器地址。
%l – 客戶機的 RFC 1413 標識 ( 參考 ) ，只有實現了 RFC 1413 規範的客戶端，才能提供此資訊。
%u – 遠程客戶端用戶名稱，用於記錄瀏覽者進行身份驗證時提供的名字，如登錄百度的用戶名 zuozewei，如果沒有登錄就是空白。
%t – 收到請求的時間（訪問的時間與時區，比如 18/Jul/2018:17:00:01+0800，時間資訊最後的 "+0800" 表示伺服器所處時區位於 UTC 之後的8小時）
%{X-Real_IP}i – 客戶端的真實ip
%r – 來自客戶端的請求行（請求的 URI 和 HTTP 協議，這是整個 PV 日誌記錄中最有用的資訊，記錄伺服器收到一個什麼樣的請求）
%>s – 伺服器返回客戶端的狀態碼，比如成功是 200。
%b – 發送給客戶端的文件主體內容的大小，不包括響應頭的大小（可以將日誌每條記錄中的這個值累加起來以粗略估計伺服器吞吐量）
%D – 處理請求的時間，以毫秒為單位
%F – 客戶端瀏覽器資訊提交響應的時間，以毫秒為單位

日誌樣例：

47.203.89.212 - - [19/Apr/2017:03:06:53 +0000] "GET / HTTP/1.1" 200 10599 50 49

Nginx統計請求和後台服務響應時間

使用默認 combined 的經典格式上擴展 response_time&upstream_response_time

nginx.conf 使用配置方式：

log_format main '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent $request_time $upstream_response_time "$http_referer" "$http_user_agent" "$http_x_forwarded_for"';

欄位說明如下：

$remote_addr – 發起請求的客戶端 IP 地址。這裡記錄的 IP 地址並不一定是真實用戶客戶機的 IP 地址，它可能是私網客戶端的公網映射地址或代理伺服器地址。
$remote_user – 遠程客戶端用戶名稱，用於記錄瀏覽者進行身份驗證時提供的名字，如登錄百度的用戶名 zuozewei，如果沒有登錄就是空白。
[$time_local] – 收到請求的時間（訪問的時間與時區，比如 18/Jul/2018:17:00:01+0800，時間資訊最後的 "+0800" 表示伺服器所處時區位於 UTC 之後的8小時）
「$request」 – 來自客戶端的請求行（請求的 URI 和 HTTP 協議，這是整個 PV 日誌記錄中最有用的資訊，記錄伺服器收到一個什麼樣的請求）
$status – 伺服器返回客戶端的狀態碼，比如成功是 200。
$body_bytes_sent – 發送給客戶端的文件主體內容的大小，不包括響應頭的大小（可以將日誌每條記錄中的這個值累加起來以粗略估計伺服器吞吐量）
$request_time – 整個請求的總時間，以秒為單位（包括接收客戶端請求數據的時間、後端程式響應的時間、發送響應數據給客戶端的時間(不包含寫日誌的時間)）
$upstream_response_time – 請求過程中，upstream 的響應時間,以秒為單位（向後端建立連接開始到接受完數據然後關閉連接為止的時間）
「$http_referer」 – 記錄從哪個頁面鏈接訪問過來的（請求頭 Referer 的內容）
「$http_user_agent」 – 客戶端瀏覽器資訊（請求頭User-Agent的內容）
「$ http_x_forwarded_for」 – 客戶端的真實ip，通常web伺服器放在反向代理的後面，這樣就不能獲取到客戶的IP地址了，通過 $remote_add拿到的IP地址是反向代理伺服器的iP地址。反向代理伺服器在轉發請求的 http 頭資訊中，可以增加 x_forwarded_for** 資訊，用以記錄原有客戶端的IP地址和原來客戶端的請求的伺服器地址。

日誌示例：

218.56.42.148 - - [19/Apr/2017:01:58:04 +0000] "GET / HTTP/1.1" 200 0 0.023 - "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36" "-"

AWK 運用

為了能理解 AWK 程式，我們下面簡單概述其基本知識，詳細內容參照上文。

AWK 程式可以由一行或多行文本構成，其中核心部分是包含一個模式和動作的組合。

pattern { action }

模式( pattern ) 用於匹配輸入中的每行文本。對於匹配上的每行文本，awk 都執行對應的動作( action )。模式和動作之間使用花括弧隔開。awk 順序掃描每一行文本，並使用記錄分隔符（一般是換行符）將讀到的每一行作為記錄，使用域分隔符( 一般是空格符或製表符 ) 將一行文本分割為多個域，每個域分別可以使用 $1, $2, … $n 表示。$1 表示第一個域，$2 表示第二個域，$n 表示第 n 個域。 $0 表示整個記錄。模式或動作都可以不指定，預設模式的情況下，將匹配所有行。預設動作的情況下，將執行動作 {print}，即列印整個記錄。

此處使用Nginx access.log 舉例，Tomcat 同學們自己舉一反三。

使用 awk 分解出Nginx access日誌中的資訊

218.56.42.148 - - [19/Apr/2017:01:58:04 +0000] "GET / HTTP/1.1" 200 0 0.023 - "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36" "-"

$0 就是整個記錄行
$1 就是訪問 IP 」218.56.42.148」
$4 就是請求時間的前半部分 「[19/Apr/2017:01:58:04」
$5 就是請求時間的後半部分 「+0000]」

以此類推……

當我們使用默認的域分割符時，我們可以從日誌中解析出下面不同類型的資訊：

awk '{print $1}' access.log # IP 地址 ($remote_addr)
awk '{print $3}' access.log # 用戶名稱 $remote_user)
awk '{print $4,$5}' access.log # 日期和時間 ([$time_local])
awk '{print $7}' access _log # URI ($request)
awk '{print $9}' access _log # 狀態碼 ($status)
awk '{print $10}' access _log # 響應大小 ($body_bytes_sent)
awk '{print $11}' access _log # 請求時間 ($request_time)
awk '{print $12}' access _log # upstream響應時間 ($upstream_response_time)

我們不難發現，僅使用默認的域分隔符，不方便解析出請求行、引用頁和瀏覽器類型等其他資訊，因為這些資訊之中包含不確定個數的空格。因此，我們需要把域分隔符修改為「，就能夠輕鬆讀出這些資訊。

awk -F\" '{print $2}' access.log # 請求行 ($request)
awk -F\" '{print $4}' access.log # 引用頁 ($http_referer)
awk -F\" '{print $6}' access.log # 瀏覽器 ($http_user_agent)
awk -F\" '{print $8}' access.log # 真實ip ($http_x_forwarded_for)

注意：這裡為了避免 Linux Shell 誤解「為字元串開始，我們使用了反斜杠，轉義了「。現在，我們已經掌握了 awk 的基本知識，以及它是怎樣解析日誌的。

使用場景舉例

此處使用Nginx access.log 舉例，Tomcat 同學們自己舉一反三

瀏覽器類型統計

如果我們想知道那些類型的瀏覽器訪問過網站，並按出現的次數倒序排列，我可以使用下面的命令：

awk -F\" '{print $6}' access.log | sort | uniq -c | sort -fr

此命令行首先解析出瀏覽器域，然後使用管道將輸出作為第一個 sort 命令的輸入。第一個 sort 命令主要是為了方便 uniq 命令統計出不同瀏覽器出現的次數。最後一個 sort 命令將把之前的統計結果倒序排列並輸出。

發現系統存在的問題

我們可以使用下面的命令行，統計伺服器返回的狀態碼，發現系統可能存在的問題。

awk '{print $9}' access.log | sort | uniq -c | sort

正常情況下，狀態碼 200 或 30x 應該是出現次數最多的。40x 一般表示客戶端訪問問題。50x 一般表示伺服器端問題。下面是一些常見的狀態碼：

200 – 請求已成功，請求所希望的響應頭或數據體將隨此響應返回。
206 – 伺服器已經成功處理了部分 GET 請求
301 – 被請求的資源已永久移動到新位置
302 – 請求的資源現在臨時從不同的 URI 響應請求
400 – 錯誤的請求。當前請求無法被伺服器理解
401 – 請求未授權，當前請求需要用戶驗證。
403 – 禁止訪問。伺服器已經理解請求，但是拒絕執行它。
404 – 文件不存在，資源在伺服器上未被發現。
500 – 伺服器遇到了一個未曾預料的狀況，導致了它無法完成對請求的處理。
503 – 由於臨時的伺服器維護或者過載，伺服器當前無法處理請求。

HTTP 協議狀態碼定義可以參閱： //www.w3.org/Protocols/rfc2616/rfc2616.html

狀態碼相關統計

查找並顯示所有狀態碼為 404 的請求

awk '($9 ~ /404/)' access.log

統計所有狀態碼為 404 的請求

awk '($9 ~ /404/)' access.log | awk '{print $9,$7}' | sort

現在我們假設某個請求 ( 例如 : URI: /path/to/notfound ) 產生了大量的 404 錯誤，我們可以通過下面的命令找到這個請求是來自於哪一個引用頁，和來自於什麼瀏覽器。

awk -F\" '($2 ~ "^GET /path/to/notfound "){print $4,$6}' access.log

追查誰在盜鏈網站圖片

有時候會發現其他網站出於某種原因，在他們的網站上使用保存在自己網站上的圖片。如果您想知道究竟是誰未經授權使用自己網站上的圖片，我們可以使用下面的命令：

awk -F\" '($2 ~ /\.(jpg|gif|png)/ && $4 !~ /^http:\/\/www\.example\.com/)\
{print $4}' access.log \ | sort | uniq -c | sort

注意：使用前，將 www.example.com 修改為自己網站的域名。

使用」分解每一行；
請求行中必須包括「.jpg」、」.gif」或」.png」；
引用頁不是以您的網站域名字元串開始（在此例中，即 www.example.com ）；
顯示出所有引用頁，並統計出現的次數。

IP相關統計

統計共有多少個不同的 IP 訪問：

awk '{print $1}' access.log |sort|uniq|wc – l

統計每一個 IP 訪問了多少個頁面：

awk '{++S[$1]} END {for (a in S) print a,S[a]}' log_file

將每個 IP 訪問的頁面數進行從小到大排序：

awk '{++S[$1]} END {for (a in S) print S[a],a}' log_file | sort -n

統計 2018 年 8 月 31 日 14 時內有多少 IP 訪問 :

awk '{print $4,$1}' access.log | grep 31/Aug/2018:14 | awk '{print $2}'| sort | uniq | wc -l

統計訪問最多的前10個 IP 地址

awk '{print $1}' access.log |sort|uniq -c|sort -nr |head -10

列出某1個 IP訪問了哪些頁面：

grep ^202.106.19.100 access.log | awk '{print $1,$7}'

統計某個 IP 的詳細訪問情況,按訪問頻率排序

grep '202.106.19.100' access.log |awk '{print $7}'|sort |uniq -c |sort -rn |head -n 100

響應頁面大小相關統計

列出傳輸大小最大的幾個文件

cat access.log |awk '{print $10 " " $1 " " $4 " " $7}'|sort -nr|head -100

列出輸出大於 204800 byte ( 200kb) 的頁面以及對應頁面發生次數

cat access.log |awk '($10 > 200000){print $7}'|sort -n|uniq -c|sort -nr|head -100

列出訪問最頻的頁面(TOP100)

awk '{print $7}' access.log | sort |uniq -c | sort -rn | head -n 100

列出訪問最頻的頁面([排除php頁面】(TOP100)

grep -v ".php" access.log | awk '{print $7}' | sort |uniq -c | sort -rn | head -n 100

列出頁面訪問次數超過100次的頁面

cat access.log | cut -d ' ' -f 7 | sort |uniq -c | awk '{if ($1 > 100) print $0}' | less

列出最近1000條記錄，訪問量最高的頁面

tail -1000 access.log |awk '{print $7}'|sort|uniq -c|sort -nr|less

PV 相關統計

統計每分鐘的請求數,top100的時間點(精確到分鐘)

awk '{print $4}' access.log |cut -c 14-18|sort|uniq -c|sort -nr|head -n 100

統計每小時的請求數,top100的時間點(精確到小時)

awk '{print $4}' access.log |cut -c 14-15|sort|uniq -c|sort -nr|head -n 100

統計每秒的請求數,top100的時間點(精確到秒)

awk '{print $4}' access.log |cut -c 14-21|sort|uniq -c|sort -nr|head -n 100

統計當天的 pv

grep "10/May/2018" access.log | wc -l

說明：

awk 『{ print $4}』：取數據的第4域（第4列）
sort：進行排序。
uniq -c：列印每一重複行出現的次數。（並去掉重複行）
sort -nr：按照重複行出現的次序倒序排列。
head -n 100：取排在前100位的IP

頁面響應時間相關統計

可以使用下面的命令統計出所有響應時間超過 3 秒的日誌記錄。

awk '($NF > 1){print $11}' access.log

注意：NF 是當前記錄中域的個數。$NF 即最後一個域。

列出 php 頁面請求時間超過3秒的頁面，並統計其出現的次數，顯示前100條

cat access.log|awk '($NF > 1 && $7~/\.php/){print $7}'|sort -n|uniq -c|sort -nr|head -100

列出相應時間超過 5 秒的請求，顯示前20條

awk '($NF > 1){print $11}' access.log | awk -F\" '{print $2}' |sort -n| uniq -c|sort -nr|head -20

蜘蛛抓取統計

統計蜘蛛抓取次數

grep 'Baiduspider' access.log |wc -l

統計蜘蛛抓取404的次數

grep 'Baiduspider' access.log |grep '404' | wc -l

小結

通過本文的介紹，我相信同學們一定會發現 linux三劍客強大之處。在命令行中，它還能夠接受和執行外部的 AWK 程式文件，支援對文本資訊進行非常複雜的處理，可以說「只有想不到的，沒有它做不到的」。

Tags: linux