Apacheのアクセスログを再生する

前に作った「http://d.hatena.ne.jp/terazzo/20090201/1233442194」のクラスの一部を使って、アクセスログの中身をリプレイするプログラムを書いてみた。

• GitHub - terazzo/CustomLogTool: CustomLogTool

ガラケーサイトで端末プロファイルを分散させつつ負荷を掛けるのに作ったんだけど、HEAD/GETしかサポートしてないので基本ステートレスでパラメータやUser-Agentの分布を実際のものに近づけたいサイトぐらいじゃないと使い途無いかも。
まだ作りかけなのであとでちょっと直す。

使い方。

ビルド*1するとcustom-log-tool-0.1.jarというのができるので、これを依存ライブラリ共々クラスパスの通ってるところに入れてsample.custom_log.tools.LogPlayerというクラスをコマンドラインから呼ぶ。

 $ java  sample.custom_log.tools.LogPlayer
usage: java sample.custom_log.tools.LogPlayer [-d <domain name>] -f <file name> [-r <rate>]
 -d <domain name>   リクエストを送信するドメイン名(省略時はlocalhost)
 -f <file name>     ログファイル指定。("-"指定時は標準入力を使用)
 -r <rate>          速度指定。倍速なら0.5を指定する。(省略時は1)

ログファイルとサーバを指定して実行すると、ログファイルの内容を元にHTTPリクエストをサーバに投げる。

 $ java sample.custom_log.tools.LogPlayer -d example.com -f logs/access_log

クラスパス設定面倒ならsbtからで呼んでも良い。

 $ sbt 'run-main sample.custom_log.tools.LogPlayer -d example.com -f logs/access_log'

注意点:

• HEADとGETしか対応してない。それ以外は無視する
• User-Agentはログのものを使用
• ログフォーマットは「%h %l %u %t \"%r\" %>s %b "%{Referer}i" "%{User-Agent}i"」を想定している
  • フォーマットを変える場合はプロパティで指定
  • 例: -Dcustom_log.format='%h %l %u %t "%r" %>s %b "%{Referer}i" "%{User-Agent}i"'
  • フォーマットに%{ヘッダ名}iが含まれている場合、それもリクエストに含める
• ログの一行目の時刻を基準として、ログに記録されている時刻とおおむね同じペースでアクセスする
  • 引数「-r」などを指定すると、その速度でアクセスする
    • 「-r 0.5」なら倍速、「-r 0」なら全速でアクセス
  • 処理が追いつかない場合はログの時刻よりも遅れる

依存ライブラリ

• commons-lang-2.6.jar
• commons-cli-1.2.jar
• httpclient-4.0.2.jar
• httpcore-4.0.1.jar
• commons-logging-1.1.1.jar

下の二つは今回は使ってないけど、前に作った部分で使っている

• JoSQL-2.2.jar
• gentlyWEB-utils-1.1.jar

中身の説明(引数のパース)

引数のパースにCommons CLI使ってみた。
HelpFormatterのprintHelp()にoptionsを渡して第三引数にtrueを指定すると、Usageを勝手に出してくれて便利。引数の順番がコントロールできないのが難点。
OptionBuilderってクラスがあったけど実装がキモイ*2ので使うの止めた。

    private static Option buildOption(String opt, boolean hasArg, String argName,
            boolean required, String description) {
        Option option = new Option(opt, hasArg, description);
        option.setArgName(argName);
        option.setRequired(required);
        return option;
    }
    public static void main(String[] args) {
        Options options = new Options();
        options.addOption(buildOption("d", true, "domain name", false,
            "リクエストを送信するドメイン名(省略時はlocalhost)"));
        options.addOption(buildOption("r", true, "rate", false,
            "速度指定。倍速なら0.5を指定する。(省略時は1)"));
        options.addOption(buildOption("f", true, "file name", true,
            "ログファイル指定。(\"-\"指定時は標準入力を使用)"));
        CommandLineParser parser = new BasicParser();
        CommandLine commandLine = null;
        try {
            commandLine = parser.parse(options, args, false);
        } catch (ParseException e) {
        }
        if (commandLine == null) {
            HelpFormatter help = new HelpFormatter();
            help.setWidth(Integer.MAX_VALUE);
            help.printHelp("java " + LogPlayer.class.getName(), options, true);
            return;
        }
        String path = commandLine.getOptionValue("f");
        String domain = commandLine.getOptionValue("d", DEFAULT_HOST);
        double rate = 1;
        try {
            rate = Double.parseDouble(commandLine.getOptionValue("r", "1"));
        } catch(NumberFormatException e) {
        }
        ....

中身の説明(HTTPアクセス)

HttpClient 4を使ってみた。

リクエストを作ってHttpClientのexecute()を呼ぶとresponseが取れる。

    private void playRecord(LogRecord logRecord) throws URISyntaxException, IOException {
...
        HttpClient httpClient = new DefaultHttpClient();
        HttpUriRequest request = prepareRequest(logRecord);
        HttpResponse response = httpClient.execute(request);

リクエストはログの内容から生成している。
ドメイン名とログのrequestUriからURLをつくり、ヘッダともろもろのパラメータをセットしている。

    // logRecordからHttpUriRequestを生成する
    private HttpUriRequest prepareRequest(LogRecord logRecord) throws URISyntaxException {
        URI uri = URIUtils.createURI("http", settings.domain, -1, logRecord.getRequestUri(),
                null, null);

        HttpUriRequest request;
        if (logRecord.getMethod().equalsIgnoreCase(HttpHead.METHOD_NAME)) {
            request = new HttpHead(uri);
        } else {
            request = new HttpGet(uri);
        }
        for (Map.Entry<String, String> headerEntry : logRecord.getHeader().entrySet()) {
            request.addHeader(headerEntry.getKey(), headerEntry.getValue());
        }
        String referer = logRecord.getReferer();
        if (!StringUtils.isEmpty(referer) && !referer.equals("-")) {
            request.addHeader("Referer", logRecord.getReferer());
        }
        // パラメータ
        HttpParams params = new BasicHttpParams();
        HttpProtocolParamBean paramsBean = new HttpProtocolParamBean(params);
        paramsBean.setVersion(HttpVersion.HTTP_1_1);
        paramsBean.setUserAgent(logRecord.getUserAgent());
        params.setBooleanParameter(ClientPNames.HANDLE_REDIRECTS, false);
        request.setParams(params);
        return request;
    }

User-AgentとRefererはlogRecord.getHeader()に含まれておらず特別扱いになっている。
あと、ClientPNames.HANDLE_REDIRECTSをfalseにセットすることでレスポンスで301や302が来てもリダイレクト先に飛ばないようにしている。

中身の説明(マルチスレッド)

java.util.concurrentのExecutorを使ってみた。
スレッド数30個固定でExecutors.newFixedThreadPool(int)で作っている。
メインスレッドでリクエストを登録し、終わったら全部のタスクが終了するまで待っている。

    // 設定されたファイル、ドメイン、速度でリクエストを再生する。
    public void play() {
        logger.debug("start playing: " + path);
        ExecutorService executor = Executors.newFixedThreadPool(THREAD_COUNT);
        try {
            InputStream in = path.equals(STDIN_NAME) ? System.in : new FileInputStream(path);
            playWith(in, executor);
        } catch (IOException e) {
            logger.warn("Error occurs while processing file:" + path + " : " + e.getMessage(), e);
        }
        executor.shutdown();
        awaitTermination(executor);
        logger.debug("complete");
    }
    // すべてのタスクが終わるまで永久に待ち続ける
    private static void awaitTermination(final ExecutorService executor) {
        new NoncancelableTask() {
            @Override
            protected boolean endure(long millis) throws InterruptedException {
                return executor.awaitTermination(millis, TimeUnit.MILLISECONDS);
            }
        }.runWithoutLimit(300 * 1000L);
    }

NoncancelableTaskはこの前作った奴の改良版です。

タスクの登録は、ログを一行ずつ読み出してLogRecordPlayerというオブジェクトを生成している。
LogRecordPlayerはRunnableを実装しているので、そのままExecutorServiceにexecute()で登録・実行できる。
Executors.newFixedThreadPool(int)はタスクのキューイングに長さMAX_INTのLinkedBlockingQueueを使っているらしく、最初に全部読み込んでしまう。メモリ使用量とかコントロールしたければ自分でpool作ったほうがよいかも。
LogParserおよびLogRecordは「http://d.hatena.ne.jp/terazzo/20090201/1233442194」で作ったもの。

    // ストリームの内容を読みだしてリクエストを生成してexecutorを使用して投げる
    private void playWith(InputStream in, ExecutorService executor) throws IOException {
        BufferedReader reader = new BufferedReader(new InputStreamReader(in));
        LogParser parser = new LogParser(format);
        String line;
        while ((line = reader.readLine()) != null) {
            try {
                final LogRecord logRecord = parser.parseLine(line);
                if (logRecord.getRequestTime() == null) {
                    continue;
                }
                if (settings == null) {
                    prepareSettings(logRecord.getRequestTime());
                }
                executor.execute(new LogRecordPlayer(logRecord, settings));
            } catch (LogParseException e) {
                logger.warn("Parse Error in file:" + path + " : " + e.getMessage(), e);
            }
        }
    }

LogRecordPlayerは設定値として処理の開始時刻とログの基準時刻を渡していて、早すぎたらsleepしてからリクエストを出している。

public class LogRecordPlayer implements Runnable {
...
    private void playRecord(LogRecord logRecord) throws URISyntaxException, IOException {
        if (! SUPPORTED_METHODS.contains(logRecord.getMethod().toUpperCase())) {
            return;
        }
        
        long requestTime = logRecord.getRequestTime().getTime(); 
        long timeToWait = (long)((requestTime - settings.recordOrigin) * settings.rate) -
                            (System.currentTimeMillis() - settings.startTime);
        if (timeToWait > 0) {
            logger.debug(String.format("waiting (%d msec)", timeToWait));
            new NoncancelableTask(){
                @Override
                protected boolean endure(long millis) throws InterruptedException {
                    Thread.sleep(millis);
                    return false;
                }
            }.runWithLimit(timeToWait);
        } else {
            logger.warn(String.format("delaying (%d msec)", -timeToWait));
        }

感想など

負荷試験用のツールっていろいろあるけど、パラメータとか端末プロフィールのバリエーションを持たせようとすると結構面倒なので、実ログ使えないかと思ったのでやってみた。

今回のアイデアは、Cookieの受け入れ機能が無かったり、順番を保障してなかったりするので、ステートフルなサイトにはまったく使えない。あと、ログに書かれた情報しか使えなく、例えばPOSTの内容が取れないので、一番負荷が高くなりそうな更新処理系が再現できないのが痛い。

複数ファイルから読み込みも複数スレッドでやろうかと思ったけど今回は使わなそうだったのでパスした。

*1:プロジェクトディレクトリで"sbt package"

*2:インスタンスのメソッドチェーンじゃなくてstaticで状態を変更していく実装