Note: This is a Japanese translation of an Adobe Experience League Knowledge Base article. Click this link for the original English version.
【目的】
AEMのrequest.logには所要時間などパフォーマンス問題の解析に役立つ情報が含まれています。本記事ではLinuxのコマンド(一部外部コマンドを含む)を用いた解析サンプルをいくつかご紹介します。
【環境】
AEM 6.5、Linux(Bash)
【対応方法】
目次
はじめに
request.logの形式
事前準備
ステップ1. データ整形
ステップ2. 再起動日時
ステップ3. 1時間ごとのアクセス件数
ステップ4. 最大同時処理件数
ステップ5. ログファイルを分割
ステップ6. リクエストレコードとレスポンスレコードを統合
解析サンプル集
サンプル1. 最も重いアクセス
サンプル2. 応答のないアクセス
サンプル3. 重いアクセス
サンプル4. 所要時間の時系列データ
サンプル5. 所要時間の最小値、平均値、中央値、最大値
サンプル6. 一定時間単位のアクセス件数
サンプル7. 一定時間単位のレスポンスステータス件数
サンプル8. アクセスの多いURL
サンプル9. request.logからaccess.logを検索
おわりに
はじめに
request.logの形式
前提となるrequest.logの形式を説明します。
request.logのサンプル:
09/Jan/2023:13:08:49 +0900 [0] -> GET /libs/granite/core/content/login.html?resource=%2F&$$login$$=%24%24login%24%24&j_reason=unknown&j_reason_code=unknown HTTP/1.1
09/Jan/2023:13:08:51 +0900 [0] <- 200 text/html;charset=utf-8 2126ms
本記事では、1行目のように「->」を含む行をリクエストレコードと呼びます。2行目のように「<-」を含む行はレスポンスレコードと呼びます。
・リクエストレコード
AEMへのアクセスを受け付けたときに記録されます。
アクセスを受け付けた日時、リクエストID、リクエストメソッド、URLを含みます。
・レスポンスレコード
AEMが応答を返したときに記録されます。
応答を返した日時、リクエストID、ステータスコード、Content-Type、所要時間(ミリ秒)からなります。
関連マニュアルをあわせてご覧ください。
https://experienceleague.adobe.com/docs/experience-manager-65/deploying/configuring/monitoring-and-m...
事前準備
ステップ1. データ整形
request.log解析の最初のステップは、ログファイルを扱いやすい形に整えることです。
$ sed 's/; /;/' request.log | ruby -r time -ne 'print $_.sub(/^[^:]+:/){|dt| Time.parse(dt).strftime("%F ")}' > request.log.norm
最初のsedコマンドは、レスポンスレコードのContent-Typeに含まれる空白を除去します。空白でフィールドを分割するときにずれが生じるのを防ぐためです。
Rubyコマンドは日付をISO 8601形式に変換し、日付と時刻を「:」ではなく空白で区切ります。
ステップ2. 再起動日時
request.logのリクエストIDはAEMを再起動したりService Packを適用したりするとリセットされます。リクエストIDが[0]のリクエストレコードは、このような操作の手掛かりになります。
$ grep -C1 -E '\[0\] ->' request.log.norm
2023-01-09 13:08:49 +0900 [0] -> GET /libs/granite/core/content/login.html?resource=%2F&$$login$$=%24%24login%24%24&j_reason=unknown&j_reason_code=unknown HTTP/1.1
2023-01-09 13:08:51 +0900 [0] <- 200 text/html;charset=utf-8 2126ms
--
2023-01-09 13:24:39 +0900 [29970] <- 200 application/json 17ms
2023-01-09 13:26:13 +0900 [0] -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371059 HTTP/1.1
2023-01-09 13:26:13 +0900 [0] <- 200 application/json 426ms
$
上記の例では13:08:49と13:26:13にリクエストIDが[0]にリセットされています。
ステップ3. 1時間ごとのアクセス件数
request.logに含まれる日時の範囲とアクセス件数を把握します。
$ grep ' -> ' request.log.norm | cut -b1-13 | sort | uniq -c
30172 2023-01-09 13
42599 2023-01-09 14
5 2023-01-09 15
$
ステップ4. 最大同時処理件数
同時に処理していたアクセス件数からAEMの負荷状況を推測できます。
$ cat request.log.norm | ruby -ane '$q ||= 0; $q += ($F[4]=="->") ? 1 : -1; puts "#{$F[1]} #{$q}"' | sort -nr -k 2 | head -3
14:37:58 196
14:37:57 196
14:37:52 196
$
AEMのデフォルトでは、Jettyの同時接続数は200です。レスポンス完了からソケットを解放するまでにタイムラグがあるので、同時処理件数が170程度を超えると新たなリクエストを受け付けられなくなってきます。
ステップ5. ログファイルを分割
AEM再起動やService Pack適用でリクエストIDがリセットされるため、このような操作を含む時間帯のrequest.logはリクエストIDが重複し解析を誤るリスクがあります。一度に扱うファイルサイズを抑えるためにも、リクエストIDが[0]のリクエストレコードをキーにrequest.logを分割します。
$ csplit -z -f reqlog request.log.norm '/\[0\] ->/' '{*}'
$ head -2 reqlog*
==> reqlog00 <==
2023-01-09 13:08:49 +0900 [0] -> GET /libs/granite/core/content/login.html?resource=%2F&$$login$$=%24%24login%24%24&j_reason=unknown&j_reason_code=unknown HTTP/1.1
2023-01-09 13:08:51 +0900 [0] <- 200 text/html;charset=utf-8 2126ms
==> reqlog01 <==
2023-01-09 13:26:13 +0900 [0] -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371059 HTTP/1.1
2023-01-09 13:26:13 +0900 [0] <- 200 application/json 426ms
$
ステップ6. リクエストレコードとレスポンスレコードを統合
リクエストレコードとレスポンスレコードをリクエストIDをキーに1行にまとめると、パフォーマンス問題が起き始めたタイミングを見つけやすいです。この後の解析サンプルでも、ここでまとめたログファイルを用います。
$ grep ' -> ' reqlog00 | sort -t' ' -k4 > req.txt
$ grep ' <- ' reqlog00 | sort -t' ' -k4 > res.txt
$ join -j4 -a1 -t' ' req.txt res.txt | sed 's/^\[//' | sort -n -k1 | sed 's/^/[/' > reqres.txt
$ sed -i '/<\-/!s/$/ 9999-99-99 99:99:99 \+0000 <- 000 NONE 999999999ms/' reqres.txt
最後のsedコマンドは、対応するレスポンスレコードがないリクエストレコードにダミーのレスポンスを加えます。
リクエストレコードのないレスポンスレコードも存在する可能性がありますが、通常、調査上の問題にはなりませんので、無視します。
まとめたログファイルは次のようになります。
$ head -3 reqres.txt
[0] 2023-01-09 13:08:49 +0900 -> GET /libs/granite/core/content/login.html?resource=%2F&$$login$$=%24%24login%24%24&j_reason=unknown&j_reason_code=unknown HTTP/1.1 2023-01-09 13:08:51 +0900 <- 200 text/html;charset=utf-8 2126ms
[1] 2023-01-09 13:08:51 +0900 -> GET /etc.clientlibs/clientlibs/granite/coralui3.css HTTP/1.1 2023-01-09 13:08:51 +0900 <- 200 text/css 87ms
[2] 2023-01-09 13:08:51 +0900 -> GET /etc.clientlibs/clientlibs/granite/typekit.js HTTP/1.1 2023-01-09 13:08:51 +0900 <- 200 application/javascript 18ms
$
解析サンプル集
サンプル1. 最も重いアクセス
応答のないアクセスを含め、所要時間の長い順にソートします。
$ sort -nr -k 15 reqres.txt | head -3
[240] 2023-01-09 13:12:31 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 9999-99-99 99:99:99 +0000 <- 000 NONE 999999999ms
[11894] 2023-01-09 13:16:21 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 2023-01-09 13:18:17 +0900 <- 500 text/html 115644ms
[12894] 2023-01-09 13:16:43 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 2023-01-09 13:18:37 +0900 <- 500 text/html 114297ms
$
サンプル2. 応答のないアクセス
ダミーの所要時間をもとに応答のないアクセスを抽出します。
$ grep 999999999 reqres.txt
[240] 2023-01-09 13:12:31 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 9999-99-99 99:99:99 +0000 <- 000 NONE 999999999ms
$
レスポンスのないアクセスを受け付けたタイミングとサーバー負荷の上昇が連動しているのであれば、このアクセスがパフォーマンス問題のトリガーとなった可能性が高いです。
$ grep pulse.data.json reqres.txt | head
[30] 2023-01-09 13:08:57 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237336993 HTTP/1.1 2023-01-09 13:08:57 +0900 <- 200 application/json 208ms
[219] 2023-01-09 13:09:59 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371022 HTTP/1.1 2023-01-09 13:09:59 +0900 <- 200 application/json 11ms
[220] 2023-01-09 13:11:00 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371023 HTTP/1.1 2023-01-09 13:11:00 +0900 <- 200 application/json 12ms
[221] 2023-01-09 13:12:02 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371024 HTTP/1.1 2023-01-09 13:12:02 +0900 <- 200 application/json 16ms
[3113] 2023-01-09 13:13:04 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371025 HTTP/1.1 2023-01-09 13:13:05 +0900 <- 200 application/json 1008ms
[6175] 2023-01-09 13:14:06 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371026 HTTP/1.1 2023-01-09 13:14:06 +0900 <- 200 application/json 353ms
[8618] 2023-01-09 13:15:08 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371027 HTTP/1.1 2023-01-09 13:15:08 +0900 <- 200 application/json 360ms
[11422] 2023-01-09 13:16:10 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371028 HTTP/1.1 2023-01-09 13:16:11 +0900 <- 200 application/json 751ms
[14224] 2023-01-09 13:17:13 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371029 HTTP/1.1 2023-01-09 13:17:13 +0900 <- 200 application/json 106ms
[17435] 2023-01-09 13:18:14 +0900 -> GET /mnt/overlay/granite/ui/content/shell/header/actions/pulse.data.json?_=1673237371030 HTTP/1.1 2023-01-09 13:18:15 +0900 <- 200 application/json 856ms
サンプル3. 重いアクセス
例えば、10秒以上かかったアクセスを抽出します。
$ grep -E '[0-9]{5}ms' reqres.txt | head -3
[232] 2023-01-09 13:12:31 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 2023-01-09 13:13:29 +0900 <- 500 text/html 58337ms
[240] 2023-01-09 13:12:31 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 2023-01-09 13:13:41 +0900 <- 500 text/html 70250ms
[262] 2023-01-09 13:12:31 +0900 -> GET /bin/querybuilder.json?type=nt%3Aunstructured&group.1_path=%2Flibs&orderby=%40jcr%3Ascore&orderby.sort=desc HTTP/1.1 2023-01-09 13:13:29 +0900 <- 500 text/html 57948ms
$
ヒット件数が多すぎる場合、grepコマンドの「[0-9]{5}」を「[0-9]{6}」に変えると、100秒以上かかったアクセスに絞れます。
サンプル4. 所要時間の時系列データ
時刻と所要時間だけを抜き出したデータは、グラフを作成するのに役立ちます。
$ cut -d' ' -f3,15 reqres.txt | sed 's/ms//' | head
13:08:49 2126
13:08:51 87
13:08:51 18
13:08:51 38
13:08:51 30
13:08:51 18
13:08:51 65
13:08:51 12
13:08:51 95
13:08:51 48
$
瞬時にレスポンスしたアクセスを省くと効率的です。次の例では1秒以上かかったアクセスのみを抽出します。
$ cut -d' ' -f3,15 reqres.txt | sed 's/ms//' | awk '$2>=1000' | head
13:08:49 2126
13:08:55 1100
13:09:04 1262
13:09:04 1277
13:09:04 1262
13:09:04 1260
13:09:04 1262
13:09:04 1269
13:09:04 1260
13:09:06 1148
$
サンプル5. 所要時間の最小値、平均値、中央値、最大値
$ cut -d' ' -f3,15 reqres.txt | sed 's/[0-9]:.. /0 /' | sed 's/ms//' | datamash -W -H --format '%8.1f' groupby 1 min 2 mean 2 median 2 max 2
GroupBy(13:00) min(2126) mean(2126) median(2126) max(2126)
13:00 1.0 210.1 38.0 3154.0
13:10 1.0 49210.5 65.0 999999999.0
13:20 11.0 3158.8 61.0 88030.0
13:10 20.0 20.0 20.0 20.0
13:20 11.0 4333.1 57.0 104216.0
13:10 11.0 11.0 11.0 11.0
13:20 8.0 3023.4 89.0 89968.0
13:10 13.0 13.0 13.0 13.0
13:20 1.0 3162.0 50.0 99087.0
$
統計処理にdatamashコマンド(https://www.gnu.org/software/datamash/)を用いています。応答のないアクセスがあるとダミー値が統計に反映されることに注意してください。
サンプル6. 一定時間単位のアクセス件数
全アクセスを10分ごとに集計します。大量のアクセス流入がパフォーマンス問題につながったかを判断する材料です。
$ cut -d' ' -f2,3 reqres.txt | cut -b1-15 | sort | uniq -c | sed 's/$/0/'
220 2023-01-09 13:00
22090 2023-01-09 13:10
7661 2023-01-09 13:20
$
POSTリクエストのみに絞る例です。典型的には、Authorでのコンテンツ編集が集中していたか、Publishへのコンテンツ公開が集中していたかを知る手掛かりになります。
$ grep ' POST ' reqres.txt | cut -d' ' -f2,3 | cut -b1-15 | sort | uniq -c | sed 's/$/0/'
1 2023-01-09 13:00
2299 2023-01-09 13:10
853 2023-01-09 13:20
$
サンプル7. 一定時間単位のレスポンスステータス件数
10分ごとのレスポンスステータス件数をdatamashコマンドで表にします。
$ cut -d' ' -f3,13 reqres.txt | sed 's/[0-9]:.. /0 /' | sort | uniq -c | sed -r 's/^ +([0-9]+) (.+)/\2 \1/' | datamash -W crosstab 1,2 sum 3
000 200 201 302 304 404 500
13:00 N/A 212 1 4 3 N/A N/A
13:10 1 8215 407 12643 N/A 1 823
13:20 N/A 2912 135 4327 N/A N/A 287
$
サンプル8. アクセスの多いURL
10分ごとにアクセスの多いURLを3件ずつ表示します。
$ for t in $(seq 130 133); do tm="${t:0:2}:${t:2:1}"; echo "${tm}0"; grep -E " ${tm}.+->" reqres.txt | cut -d' ' -f6,7 | sort | uniq -c | sort -nr | head -3; done
13:00
7 GET /libs/granite/csrf/token.json
5 GET /content/dam/wknd/en/.permissions.json?privileges=jcr%3AmodifyAccessControl
4 GET /libs/granite/security/currentuser.json
13:10
6326 GET /
6317 GET /index.html
6312 GET /aem/start.html
13:20
2173 GET /aem/start.html
2168 GET /index.html
2159 GET /
13:30
$
サンプル9. request.logからaccess.logを検索
特定のリクエストIDに対応するaccess.logを抽出します。
$ grep -E '\[12345\]' reqres.txt | cut -d' ' -f3-8,13 | sed 's/-> /./' | sed -r 's/ ([0-9]{3})$/. \1/' | xargs -I{} grep {} access.log
127.0.0.1 - admin 09/Jan/2023:13:16:30 +0900 "POST /bin/wcmcommand HTTP/1.1" 200 1979 "-" "Java"
127.0.0.1 - admin 09/Jan/2023:13:16:30 +0900 "POST /bin/wcmcommand HTTP/1.1" 200 1853 "-" "Java"
127.0.0.1 - admin 09/Jan/2023:13:16:30 +0900 "POST /bin/wcmcommand HTTP/1.1" 200 3585 "-" "Java"
127.0.0.1 - admin 09/Jan/2023:13:16:30 +0900 "POST /bin/wcmcommand HTTP/1.1" 200 1729 "-" "Java"
127.0.0.1 - admin 09/Jan/2023:13:16:30 +0900 "POST /bin/wcmcommand HTTP/1.1" 200 1729 "-" "Java"
127.0.0.1 - admin 09/Jan/2023:13:16:30 +0900 "POST /bin/wcmcommand HTTP/1.1" 200 3585 "-" "Java"
$
同じ時刻に同じURLへのアクセスが複数あると、access.logは複数レコードがヒットします。
おわりに
本記事のサンプルがパフォーマンス問題解析の参考になれば幸いです。
掲載したコマンドラインはCentOS 7.5およびUnbuntu 22.04LTSで動作確認を行いました。環境によってはコマンドのバージョンやバリエーションによっては期待通りの動作にならない場合があります。ご利用の環境にインストールされているコマンドにあわせて適宜調整をお願いします。
＜留意事項＞
・上記は以下記事の抄訳/翻訳となります。
KB記事タイトル(英語). Adobe Experience Manager: Examples of request.log analysis, January 24, 2023, https://experienceleague.adobe.com/docs/experience-cloud-kcs/kbarticles/KA-21309.html, (参照 2023-01-31).
・本記事にいただいたコメントへの返信はお約束できません。あらかじめご了承ください。
