同じマシンにインストールされている Apache httpd サーバーを呼び出すクライアント ソフトウェアがあります。Apache を呼び出す前に、ログ エントリが記録されます。
2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels
ご覧のとおり、呼び出しは現地時間の 13:27:43 に行われました。ドメイン mydomain.com は、同じマシンの外部 IP を解決します。
しかし、access.logファイルを見ると、タイムスタンプ[1]が5秒後のログエントリが見つかります。
[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels
これはデーモン モードで実行されている mod_wsgi ベース サーバーですが、関連があるかどうかはわかりません (Apache レベルでの要求の場合、タイム スタンプは開始になるはずです)。
この 5 秒の原因を突き止めるにはどうすればよいでしょうか?
乾杯、ボアズ
説明: [1] - タイムスタンプはリクエストが開始エントリはリクエストが終了したときにログに書き込まれますが、時間はリクエストの開始時になります。
答え1
これは、アクセスログが終わり要求の開始ではなく、要求の最後の時点です。したがって、12:00 に要求を行い、完了するまでに 1 分かかる場合、エントリは 12:01 まで書き込まれません。転送されたバイト数などが含まれる可能性があるという事実は、このことの確かな指標です。
あるホストから別のホストに traceroute を実行して、実際にリクエストが受信されているかどうかを確認することもできます。ルーティング中に遅延が見られる場合は、問題の原因がわかります。
答え2
確認すべき点が 2 つあります。
- サーバー上で mydomain.com という名前を解決するのにかかる時間 (コメントの TokenMacGuy による)
- リクエストの完了時にログが書き込まれるスクリプトの実行時間