タブでapacheのログを区切る件について

apacheのログをタブで区切ると良い、という話を、nginx + unicornでrails3.1が動作する環境を作る - A Peak Never Ending !のnginxの設定ファイルのログ出力周りを見ていて思い出した。

/etc/nginx/nginx.conf:
（中略）
    log_format  main '$msec\t'
        '$status\t'
        '$request_time\t'
        '$remote_addr\t'
        '$upstream_addr\t'
        '$upstream_response_time\t'
        '$request\t'
        '$http_referer\t'
        '$http_user_agent';

その話の記事は以下になります。
404 Blog Not Found:tips - ApacheのLogフォーマットの方を変えて高速化

Benchmark: running rx_naive, rx_optim, tsv for at least 3 CPU seconds...
  rx_naive:  3 wallclock secs ( 3.15 usr +  0.00 sys =  3.15 CPU) @ 2417.71/s (n=7612)
  rx_optim:  3 wallclock secs ( 3.78 usr +  0.00 sys =  3.78 CPU) @ 78526.94/s (n=296930)
       tsv:  4 wallclock secs ( 3.02 usr +  0.00 sys =  3.02 CPU) @ 646447.96/s (n=1954495)
             Rate rx_naive rx_optim      tsv
rx_naive   2418/s       --     -97%    -100%
rx_optim  78527/s    3148%       --     -88%
tsv      646448/s   26638%     723%       --

タブ区切りをparseすると、実に10倍程度、早い。

#!/usr/local/bin/perl
use strict;
use warnings;
use Benchmark qw/timethese cmpthese/;

my $logline =
q{localhost.local - - [04/Oct/2007:12:34:56 +0900] "GET /apache_pb.gif HTTP/1.1" 200 2326 "http://www.dan.co.jp/" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en-US; rv:1.8.1.7) Gecko/20070914 Firefox/2.0.0.7"};

my (@logline) =
  ( $logline =~
      m!^(.*) (.*) (.*) \[(.*)\] "(.*)" (.*) (.*) "(.*)" "(.*)"! );

my $tsv = join "\t", @logline;

cmpthese(
    timethese(
        0,
        {
            rx_naive => sub {
                my (@l) =
                  ( $logline =~
m!^(.*) (.*) (.*) \[(.*)\] "(.*)" (.*) (.*) "(.*)" "(.*)"!
                  );
            },
            rx_optim => sub {
                my (@l) =
                  ( $logline =~
m!^([^\s]*) [^\s]* [^\s]* \[([^]]*)\] "([^"]*)" ([^\s]*) [^\s]* "([^"]*)" "([^"]*)"!
                  );
            },
            tsv => sub { my (@l) = split /\t/, $logline },
        }
    )
);

かなり前にapacheのログを自分で解析するプログラムを書いたときに、とてもお世話になったコードです。

で、実はこのコードには問題があって、

31c31
<             tsv => sub { my (@l) = split /\t/, $logline },
---
>             tsv => sub { my (@l) = split /\t/, $tsv },

というpatchを当てないと正確な値が出ないのだと思うのです。perlを書いたことがないので正しいのかどうか分からんけれども。

結果はこうなります。

$ ./ben2.pl
Benchmark: running rx_naive, rx_optim, tsv for at least 3 CPU seconds...
  rx_naive:  3 wallclock secs ( 3.13 usr +  0.00 sys =  3.13 CPU) @ 4771.25/s (n=14934)
  rx_optim:  3 wallclock secs ( 3.12 usr +  0.00 sys =  3.12 CPU) @ 168081.41/s (n=524414)
       tsv:  2 wallclock secs ( 3.32 usr +  0.00 sys =  3.32 CPU) @ 278219.28/s (n=923688)
             Rate rx_naive rx_optim      tsv
rx_naive   4771/s       --     -97%     -98%
rx_optim 168081/s    3423%       --     -40%
tsv      278219/s    5731%      66%       --

それでも66%増なので、タブ区切りの方が良いのです。前述のnginxの設定ファイルのように、タブ区切りを採用しています。

この件について、twitterでもはてブでも指摘している人は居なかったので、
404 Blog Not Found:コードについて書く方がコードを書くより読まれる現実

読者のほとんどは、コードを読みたくないのだ、ということ。
ざっくり、記事中にコードが一行あるだけで読者は半減する。

ということは、そのとおりなんだろうなぁ、と思いました。

おわり。