2009/07/18

Document Actions

リクエスト処理時間が数時間? - HTTPサーバのタイムアウト設定について -

追記レスポンス処理時間という用語があれなのでリクエスト処理時間に書き換えました。レスポンス処理時間と書いていた理由は、「レスポンスを返すまでの時間」を長いと思い「レスポンス処理時間」と書き換えたためでした。

最近、某所でApache(背後にTomcat)のアクセスログに残っているリクエスト処理時間(CustomLogのフォーマット指定%T)が数時間なのを見ました。数時間のリクエスト処理時間が起きるのか不明だったので確認してみました。

結論から言えば、背後のTomcatのレスポンスが遅ければ普通に発生します。

以下、タイムアウトした時にログを見るヒントとしてログの抜粋を載せます。

Tomcatと比較するために、最初に(Apacheの)CGIで確認してみます。ただ5分(300秒)スリープするスクリプトです。

#!/bin/sh
sleep 300
echo "Content-type: text/plain"
echo
echo 'xx'

ApacheのTimeout設定値(デフォルトは300秒)によって動作が変わります。Timeout値の時間の間、Webブラウザはレスポンスを待ち続けます。

httpd.confでTimeout値を30(秒)にすると、30秒後にWebブラウザがエラー画面になります。ステータスコードは500です。Apacheのアクセスログは次のようになります(一部抜粋)。

192.168.80.11 - - [14/Jul/2009:20:36:08 +0900] "GET /cgi-bin/sleep HTTP/1.1" 500 535

Apacheのerror.logは次のような感じです。

[Tue Jul 14 20:36:38 2009] [warn] [client 192.168.80.11] Timeout waiting for output from CGI script /usr/local/apache22/cgi-bin/sleep
[Tue Jul 14 20:36:38 2009] [error] [client 192.168.80.11] Premature end of script headers: sleep

内部的にはCGIのプロセス呼び出しに対してTimeout値を流用しているので、このような動作になります。CGIの場合は、ApacheのTimeout値でタイムアウトを制御可能という結論です。

なお、Apacheのアクセスログに載る時刻はリクエストを受けた時刻であることに注意してください。

さて、本題のTomcatです(Tomcat6を使っています)。

遅延のあるサーブレットアプリを模倣するため次のコードにしました。リクエストURLのパスは/long/myにしています。

下記コードでは10分間スリープしています。一応、30分スリープでも同じ傾向なのを確認しています(すべては確認していません)。

import java.io.*;
import javax.servlet.*;
import javax.servlet.http.*;

public class My extends HttpServlet {
    public void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        try {
            Thread.sleep(1000*60*10);  // 10min
        } catch (InterruptedException e) {
            System.out.println("interrupted");
        }
        PrintWriter out = resp.getWriter();
        out.print("<html><head><title>hello servlet</title></head>");
        out.print("<body>");
        out.print("long time");
        out.print("</body></html>");
    }    
}

直接、WebブラウザからTomcatにアクセスするとWebブラウザは律義に10分間待ちます。Tomcatも特に接続を切る気配はありません。ちなみにTomcatのアクセスログに載る時刻はレスポンスを返した時刻です。Apacheと異なるので注意してください。

次にTomcatの前にApacheを配置します。mod_proxy_httpとmod_jkで確認しました。結論から言えば、どちらもデフォルト設定では、Webブラウザが10分間待ちます。Apacheのリクエスト処理時間(%T)は10分になります。なるほど、リクエスト処理時間が数時間になっても不思議はありません。

mod_proxy_httpとmod_jkで効果のあるタイムアウト設定をまとめます。

mod_proxy_httpの場合に効く設定はProxyTimeout値です。ProxyTimeout値のデフォルト値はTimeout値なので、ProxyTimeout値が未設定の場合、Timeout値が間接的に効きます。ProxyTimeout値もProxyPassのtimeout値のデフォルト値で、直接効くのはProxyPassの設定です。

このタイムアウト設定が効くと、裏側のTomcatがレスポンスを返さなくてもApacheがステータスコード502をWebブラウザに返します。この時のApacheのアクセスログは次のようになります。

192.168.80.11 - - [14/Jul/2009:19:19:08 +0900] "GET /long/my HTTP/1.1" 502 393

Apacheのerror.logは次のようになります。

[Tue Jul 14 19:19:38 2009] [error] [client 192.168.80.11] (70007)The timeout specified has expired: proxy: error reading status line from remote server hako
[Tue Jul 14 19:19:38 2009] [error] [client 192.168.80.11] proxy: Error reading from remote server returned by /long/my

Tomcatのアクセスログは次のように普通にステータスコード200になります(このログがでた時点では既にApacheがエラーを返しています)。このログだけ見るとだまされます。

127.0.0.1 - - [14/Jul/2009:19:20:36 +0900] "GET /long/my HTTP/1.1" 200 118

mod_jkの場合、次のようにsocket_timeoutで設定可能です。以下の例は10秒にしています。

JkWorkerProperty worker.ajp13.socket_timeout=10

10秒経つと、(裏側のTomcatがレスポンスを返さなくても)Apacheが502をWebブラウザに返します。アクセスログは次のようになります。レスポンスサイズがmod_proxy_httpと異なるのは、エラー画面の文字数が異なるためです。

192.168.80.11 - - [14/Jul/2009:19:56:15 +0900] "GET /long/my HTTP/1.1" 502 232

mod_jkのログは次のようになります。これだけ見るとTomcatがダウンしているように読めますが、単にレスポンスが遅いだけでもこのログになります。

[Tue Jul 14 19:56:27.898 2009] [12284:3084311392] [info] ajp_connection_tcp_get_message::jk_ajp_common.c (1150): (ajp13) can't receive the response header message from tomcat, network problems or tomcat (127.0.0.1:8009) is down (errno=11)
[Tue Jul 14 19:56:27.898 2009] [12284:3084311392] [error] ajp_get_reply::jk_ajp_common.c (1962): (ajp13) Tomcat is down or refused connection. No response has been sent to the client (yet)
[Tue Jul 14 19:56:27.899 2009] [12284:3084311392] [info] ajp_service::jk_ajp_common.c (2447): (ajp13) sending request to tomcat failed (recoverable),  (attempt=1)
[Tue Jul 14 19:56:40.000 2009] [12284:3084311392] [info] ajp_connection_tcp_get_message::jk_ajp_common.c (1150): (ajp13) can't receive the response header message from tomcat, network problems or tomcat (127.0.0.1:8009) is down (errno=11)
[Tue Jul 14 19:56:40.000 2009] [12284:3084311392] [error] ajp_get_reply::jk_ajp_common.c (1962): (ajp13) Tomcat is down or refused connection. No response has been sent to the client (yet)
[Tue Jul 14 19:56:40.000 2009] [12284:3084311392] [info] ajp_service::jk_ajp_common.c (2447): (ajp13) sending request to tomcat failed (recoverable),  (attempt=2)
[Tue Jul 14 19:56:40.000 2009] [12284:3084311392] [error] ajp_service::jk_ajp_common.c (2466): (ajp13) connecting to tomcat failed.
[Tue Jul 14 19:56:40.000 2009] [12284:3084311392] [info] jk_handler::mod_jk.c (2615): Service error=0 for worker=ajp13

Tomcatのアクセスログはmod_proxy_httpの時と同じように普通に200レスポンスを返すログです。Tomcatのログだけ見ているとだまされます。

192.168.80.11 - - [14/Jul/2009:20:06:15 +0900] "GET /long/my HTTP/1.1" 200 137

ApacheにはTimeoutとKeepAliveTimeoutというふたつの代表的なタイムアウト設定があります。今回の件にはどちらも直接的には効きません。なぜなら、Timeout値はWebブラウザに対するrecv(2)とsend(2)のタイムアウト設定で、KeepAliveTimeout値はWebブラウザにレスポンスを返した後、次のリクエストを受けるまでのタイムアウト設定だからです。

ソースは見ていませんが、Tomcat側のconnectionTimeout設定とkeepAliveTimeout設定は、それぞれApacheのTimeoutとKeepAliveTimeoutに相当する設定のようなので、今回の件には効きません。

Category(s): カテゴリなし

The URL to Trackback this entry is:: http://dev.ariel-networks.com/Members/inoue/timeout/tbping

Add comment

You can add a comment by filling out the form below. Plain text formatting.

Author (Required)

URL

Title (Required)

Comment (Required)

Verification Code

This helps us prevent automated spamming.

Remember your information on cookie?

ありえるえりあ

Sections

Personal tools

Document Actions

リクエスト処理時間が数時間? - HTTPサーバのタイムアウト設定について -