HAProxy 1.6 のHTTP log formatについて
こんにちは、じょにーです。
今日はHAProxyのHTTPモードにおけるデフォルトのログフォーマットの中で重要そうなものについて簡単に解説します。
公式ドキュメントは以下のサイトです。
HAProxy version 1.6.14 - Configuration Manual
サンプルログはこちら。
Nov 18 02:20:39 localhost haproxy[10745]: 10.1.0.101:57034 [18/Nov/2018:02:20:39.017] http-in backend_servers/server-01-06 0/0/0/3/3 200 3632 - - ---- 14/14/7/1/0 0/0 "GET /doku.php HTTP/1.1" Nov 18 02:17:34 localhost haproxy[10745]: 10.1.0.103:37640 [18/Nov/2018:02:17:34.107] http-in backend_servers/<NOSRV> 0/-1/-1/-1/0 503 212 - - SC-- 1791/1791/1790/0/0 0/0 "GET /doku.php HTTP/1.1"
HTTP log formatについて
各ログの形式は以下のようになります。
| 名称 : リクエスト例 | 200(OK) | 503(Service Unavailable) |
|---|---|---|
| 時刻 | Nov 18 02:20:39 | Nov 18 02:17:34 |
| HAProxyのIP? | localhost | localhost |
| 1. process_name '[' pid ']:' | haproxy[10745] | haproxy[10745] |
| 2. client_ip ':' client_port | 10.1.0.101:57034 | 10.1.0.103:37640 |
| 3. '[' request_date ']' | [18/Nov/2018:02:20:39.017] | [18/Nov/2018:02:17:34.107] |
| 4.frontend_name | http-in | http-in |
| 5. backend_name '/' server_name | backend_servers/server-01-06 | backend_servers/<NOSRV> |
| 6. TR '/' Tw '/' Tc '/' Tr '/' Ta* | 0/0/0/3/3 | 0/-1/-1/-1/0 |
| 7. status_code | 200 | 503 |
| 8. bytes_read* | 3632 | 212 |
| 9. captured_request_cookie | - | - |
| 10. captured_response_cookie | - | - |
| 11. termination_state | ---- | SC-- |
| 12. actconn '/' feconn '/' beconn '/' srv_conn '/' retries* | 14/14/7/1/0 | 1791/1791/1790/0/0 |
| 13. srv_queue '/' backend_queue | 0/0 | 0/0 |
| 16. '"' http_request '"' | "GET /doku.php HTTP/1.1" | "GET /doku.php HTTP/1.1" |
重要そうなものは，3、6、7、12です。
3はリクエストを受信した時刻です。
7は応答のステータスコード。
6はリクエストの処理過程でどこでどのくらい時間がかかったのか示したもののようです。
TRは，最初のバイトが受信された後、クライアントからの完全なHTTP要求（本文を数えずに）を待つのに費やされた合計時間。
Twは．さまざまなキューで待機する合計時間。
Tcは，リトライを含む最終的なサーバーへの接続の確立を待機する合計時間。
Trは，サーバーがデータをカウントせずに完全なHTTP応答を送信するのを待機する合計時間。
Ta*は、要求がHAProxyでアクティブなままだった時間であり、要求の最初のバイトが受信されてから応答の最後のバイトが送信されたまでの合計時間をそれぞれ示しています。
様々なキューというのは基本的にコネクションキューを指すようです。
以下が公式ドキュメントにある6のTiming Eventの説明図です。
first request 2nd request
|<---------------------->|<-------------- ...
t t ...
---|----|----|----|----|----|----|--
: Tq Tw Tc Tr Td : Tq ...
:<--------- Tt --------->:
12は接続を維持しているコネクション数などを示しています。
actconnは，セッションがログに記録されたときの、プロセス上の同時接続の合計数。
feconnは，セッションがログに記録されたときのフロントエンドでの同時接続の合計数。
beconnは，セッションがログされたときにバックエンドによって処理された同時接続の総数。
srv_connは，セッションがログに記録されたときにサーバーでアクティブな同時接続の合計数。
retries*は，サーバーに接続しようとしたときにこのセッションで発生した接続再試行回数です。
まとめ
以上、簡単に重要そうなフォーマットについて解説しました。
6のTiming Eventを解析すればどこがボトルネックになっているのか分かりますし、
12の connectionsを見ればロードバランサ自体がボトルネックになっている場合に気づきやすいのかなと思います。
