2012年8月アーカイブ

「君のPSGIファイルを僕のミドルウェアでいっぱいにしたい」という台詞を思いついたけど使い道がない kazeburo です

似たようなログ記録モジュールはCPANにいくつかあるんだけど、File::RotateLogsっていうのを書いてCPANにあげました

https://metacpan.org/release/File-RotateLogs

特徴は以下の通り

  • strftimeベースのファイル名生成
  • 秒数指定のrotation
  • rotation時に最新のファイルへのsymlink
  • 古いログはforkしてバックグラウンドで削除

使い方

Proclet と組み合わせると

my $app = builder {
    enable 'AccessLog';
    $app;
};
my $rotatelogs = File::RotateLogs->new(
    logfile => '/path/to/app_log.%Y%m%d%H%M',
    linkname => '/path/to/app_log',
    rotationtime => 3600,
    maxage => 86400,
);
my $proclet = Proclet->new(
    logger => sub { $rotatelogs->print(@_) },
);
$proclet->service(
    code => sub {
        my $loader = Plack::Loader->load(
            'Starlet',
            port => 5432,
            max_workers => 4,
        );
        $loader->run($app);
    },
    tag => 'web'
);
$proclet->service(
    code => sub {
        $worker->run
    },
    tag => 'worker'
);
$proclet->run;

これで1日分のworkerとwebサーバのログを記録しておけるし、tail -F /path/to/app_log だけでログをずっと追いかけて行く事ができます。

このモジュール、始めはPlack::Middleware::AxsLogというAccessLog+αなミドルウェアを作っていたんだけど、どうみても単体の方が便利なので単独のモジュールにしてリリースしました。どうぞお試しください

kazeburo さんの Proclet をもちいた劣化 foreman の実装 - tokuhirom’s blog.」に

STDOUT にタグつけたりはしてないけど、とりあえず起動はできる。STDOUT にタグつけるのは pipe で処理かまさないとだめなのでちと面倒

と書かれていたので、その面倒な事をProclet側で実装してみた。

https://metacpan.org/release/KAZEBURO/Proclet-0.09

プロセスの数だけpipeを作って、各プロセスでSTDERRとSTDOUTをpipeに結びつけ、ログ処理専用workerがそれをselectしつつ読み出すという設計になっています

使い方

my $proclet = Proclet->new(
    color => 1
);
$proclet->service(
    code => sub {
        my $loader = Plack::Loader->load(
            'Starman',
            port => 5432,
        max_workers => 4,
        );
        $loader->run($app);
    },
    tag => 'web'
);
$proclet->service(
    code => sub {
        exec('/usr/bin/memcached','-vv','-p','11211');
    },
    tag => 'memcached'
);
$proclet->run;

こんな感じに書いて起動すると↓のようになります

proclet.png

これで一歩foremanに近づいたような気がします

色がつくオプションはデフォルト無効になっています。

zshのzargsコマンドの使い方 - 技術メモ帳

それFile::Zglobでできるかもいうことでperlで書いてみた。zshじゃなくても使える。

zargsはxargs相当のコマンド実行機能もあるけど、ファイル一覧さえ作れればxargs使えばいい。

#!/usr/bin/env perl

use strict;
use warnings;
use File::Zglob;
use Getopt::Long;
use Pod::Usage;

our $VERSION=$File::Zglob::VERSION;

GetOptions (
    'h|help' => \my $help,
    'v|version' => \my $version,
) or pod2usage(2);
$version and do { print "zglob: $VERSION\n"; exit 0 };
pod2usage(1) if $help;

my @args = @ARGV;
pod2usage(2) unless $args[0];

print $_,"\n" for zglob($args[0]);


__END__

=head1 NAME

zglob - extended globs

=head1 SYNOPSIS

 zglob ([options] --) pattern

 Options:
    -help -h                       brief help message

サンプル

$ zglob '**/*.pm' | head
blib/lib/CloudForecast.pm
blib/lib/Shirahata.pm
blib/lib/CloudForecast/Component.pm
blib/lib/CloudForecast/ConfigLoader.pm
blib/lib/CloudForecast/Data.pm
blib/lib/CloudForecast/Gearman.pm
blib/lib/CloudForecast/Host.pm
blib/lib/CloudForecast/Ledge.pm
blib/lib/CloudForecast/Log.pm
blib/lib/CloudForecast/Radar.pm

パターンをquoteする必要があるのが面倒だ。

この手のツールは便利かもしれないけどサーバに入れてまわるのが面倒なので普通に入っているfindなどのコマンドを使った方が結局、楽な罠

「初めてのPerl 第6版」が発売されました | 近藤嘉雪のプログラミング工房

「初めてのPerl 第6版」がでたそうです - tokuhirom’s blog.

「初めてのPerl 第6版」がでたそうです - Islands in the byte stream

Perl 5.14 に対応してモダンな書き方の説明になっているそうですので、Perl 5.8 のままおいていかれてる人や Perl 5.6 のままの知識の人などはこの機会に再入門してみてもよいのでは?


訳者の近藤さんのYAPC::Asia 2012でのTalkの裏番組のブログがこちらです

なんかtwitterで書いたらウケたっぽいので

某サービスのAPIへの問い合わせ件数を調べると、毎時 0分台(0秒から59秒)のアクセスは1分から59分までの1分間の平均アクセス数の5倍から8倍にもなります。

これはおそらく、crontabの設定が

0 * * * * /path/to/call_foreign_api

になっていることが多いからじゃないかなぁと思うのです。

その結果、サーバのロードアベレージは

cron_la.png

このように毎時0分だけ跳ね上がってしまいます。サービスを快適に提供できなくなる可能性があるので、APIの利用を制限したり、サーバを追加しなければなりません。これはサービス利用者、サービス提供者にとってあまりうれしくない事態。

なので、外部APIに問い合わせる場合はできるだけ「0分」を外しておくのをオススメします。11分とか13分とか17分とか19分、23分とかだといいですね。

こういった情報がAPIのドキュメントページにあるともっといいと思ってます

以前(2010年)に「アプリケーションがマルチスレッドでもマルチコアCPUを活かせない件」というエントリにてCPUのコアが増えても割り込み処理が分散されないのでスケールされないと書いたけど、その後Linux KernelにRPS/RFSなる機能が追加され、割り込み処理が分散できるようになり、CentOS 6.2 でも使えるらしいので試してみました。

RPS/RFSについての紹介は

が詳しい。2番目のはほぼ読めないけど、性能比較のグラフが分かりやすい。

今回試したサーバは、

  • OS: CentOS 6.2
  • Kernel: kernel-2.6.32-279.2.1.el6.x86_64
  • CPU: Intel Xeon E3-1220L (2コア HT有効で4スレッド TDP 20W!)
  • NIC: Intel i82574L
  • NIC Driver: e1000e

という構成です。

この構成ではmulti queue (RSS: Receive Side Scaling)が有効ではないようなので割り込み処理が1コアに集中します

$ cat /proc/interrupts 
           CPU0       CPU1       CPU2       CPU3       
 34:   12093133          0          0          0  IR-PCI-MSI-edge      eth1-rx-0
 35:   12032740          0          0          0  IR-PCI-MSI-edge      eth1-tx-0
 36:          2          0          0          0  IR-PCI-MSI-edge      eth1

interruptsをみると、CPU0に集中しているのがわかります

この状態でnginx(worker_processes 4)を起動し、別のサーバからweighttpを使って負荷を掛けたときのmpstatが次の通り。

  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
  all   11.79    0.00   20.86    0.05    0.00   15.72    0.00    0.00   51.59
    0   16.60    0.00   24.60    0.00    0.00   52.80    0.00    0.00    6.00
    1    4.32    0.00    9.67    0.00    0.00    1.44    0.00    0.00   84.57
    2   22.58    0.00   42.34    0.00    0.00    6.65    0.00    0.00   28.43
    3    3.37    0.00    6.94    0.20    0.00    1.98    0.00    0.00   87.50

CPU0だけ「%soft」を使い、%idleが残り6%となってしまっています。

次にRPS/RFSを有効にします

echo "f" > /sys/class/net/eth1.xx/queues/rx-0/rps_cpus
echo 4096 > /sys/class/net/eth1.xx/queues/rx-0/rps_flow_cnt
echo 32768 > /proc/sys/net/core/rps_sock_flow_entries

cat /sys/class/net/eth1.xx/queues/rx-0/rps_cpus
00000000,0000000f

今回のサーバではVLANを使っているのでデバイスは「eth1.xx」です。ちなみに、multi queue(RSS)をサポートしているNICだと、rx-0のところがいくつか増えますが、今回は1つです

これで再度同じ負荷を掛けてみたときのmpstatが次の通り。

  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
  all   10.49    0.00   18.99    0.00    0.00   16.85    0.00    0.00   53.67
    0   16.90    0.00   29.18    0.00    0.00   29.18    0.00    0.00   24.75
    1    7.71    0.00   14.17    0.00    0.00    9.58    0.00    0.00   68.54
    2   10.88    0.00   20.33    0.00    0.00   14.99    0.00    0.00   53.80
    3    6.20    0.00   12.00    0.00    0.00   13.60    0.00    0.00   68.20

「%soft」の項目がCPU0以外にも分散されているのが分かります。CPU0のidleもまだ30%近くあります。

今回のテストではweighttpの結果に差はあまりありませんでしたが、↓こういうサーバに投入してみたいなと思っているところです

memcached-softirq.png

このサーバではmemcachedが動いていて、CPUは4コア(8スレッド)、ピーク時に割り込み処理を担当するCPUは100%近い使用率となっていそうなので何かしらの対応が必要となってる

riywoさんの「Perlでssh tail -fして目的の行が来たら終了する」に便乗するコネタ。

ログをtailしながら(ほぼ)リアルタイムで解析していくworkerの処理がどれくらい遅延しているのか確認して、それをgrowthforecastでグラフ化したいなと思ったので以下のようなスクリプトを書いてcronで実行しているよという話

#!/usr/bin/perl

use strict;
use Time::Piece;
use LWP::UserAgent;

my $worker = `/usr/bin/pgrep worker.pl`;
chomp($worker);
die "couldnot find worker pid" unless $worker;

pipe my $logrh, my $logwh
    or die "Died: failed to create pipe:$!";
my $pid = fork;
if ( ! defined $pid ) {
    die "Died: fork failed: $!";
} 
elsif ( $pid == 0 ) {
    close $logrh;
    open STDERR, '>&', $logwh
        or die "Died: failed to redirect STDERR";
    close $logwh;
    exec("/usr/bin/strace",'-s','300','-p',$worker,'-e','trace=read');
    die "Died: exec failed: $!";
}

#parent
close $logwh;
my $time;
my $line = 0;
while(<$logrh>){
    if ( m!\[(\d{2}/\w{3}/\d{4}:\d{2}:\d{2}:\d{2}) \+0900\]! ) {
        $time = $1;
        last;
    }
    $line++;
    last if $line > 3000;
}

kill($pid);
close $logrh;
while (wait == -1) {}

die "couldnot find time within 3000 lines" unless $time;
my $time = Time::Piece->strptime($time,q!%d/%b/%Y:%H:%M:%S!)->epoch;
my $delay = time() - $time + 3600*9;

$ua->post("http://growthforecast.local/api/worker/rag/host", {
    number => $delay     
});

まずpipeをつくり、fork。子プロセスで標準エラーをpipeに結びつけて、straceをreadのシステムコールだけトレースするようにして実行。straceの結果は親プロセスでpipeから読み取り、アクセスログの時間っぽい文字列を探す。文字列が見つかったらループを抜け、子プロセスを停止し、現在時間との差を計算して、GrowthForecastにポスト。

強引な手だけど見える化で得たものプライスレス

この記事は「Apache上のPerl FastCGIはCustomLogにデータを書くことができるか?ついでにmod_perlでのお話」へのレスです

「FCGIので動いているアプリケーションがあって、コードの中の変数をapacheのLOGに出したいのですよ。」とのことらしいので昔書いた mod_copy_header というモジュールを思い出しながら再現して github に置いた

https://github.com/kazeburo/mod_copy_header



これを使うと任意のレスポンスヘッダを Apacheのnoteにコピーすることができます。あとはmod_headersでレスポンスヘッダを消すなり、CustomLogでログに記録するなりできます。

なぜこのモジュールが必要なのかというと、ヘッダだけでやろうとした場合、元記事でも紹介されてますが、

<Location ..>
  CustomLog ".. %{X-Foobar}o"
</Location>

のように設定すれば確かにログに任意の情報を残すことができます。しかし、ユーザにヘッダを見せたくない場合は使えません。

そこでmod_headersを使ってログの削除を試みるのですが

<Location ..>
  Header unset X-Foobar
  CustomLog ".. %{X-Foobar}o"
</Location>

これだとログの記録より先にmod_headersが先に動いてしまうので、ログには空っぽの「-」しか記録できません。

そこで、mod_copy_header を使うと、まず(mod_headersより先に)ヘッダをnoteにコピーし、mod_headersでヘッダを削除。ログはnoteを参照する。ということができるので、うまく記録ができます

LoadModule copyheader_module   modules/mod_copyheader.so

<Location /foobar>
  ProxyPass http://...
  <IfModule copyheader_module>
    CopyHeaderActive On
    CopyHeader X-Foobar
  </IfModule>
  Header unset X-Foobar
  LogFormat "... %{X-Foobar}n" xfoobar
  CustomLog "logs/access_log" xfoobar
</Location>

Reverse ProxyとApplication Serverの2段構成になっていて、Applicationのなんらかの値(処理にかかった時間やユーザ情報)をReverse Proxyのログに残した場合などに使えますね!

MySQLを運用していて特定の時間帯だけ更新クエリが増えているのを見つけたときにバイナリログを探ったりすることはまぁまぁあると思います。最近はmysqlbinlogとperlのワンライナーをつかって調べています

mysqlbinlogをつかって特定の時間帯のログを調べるのは

$ mysqlbinlog --start-datetime="2012-07-31 09:41:00" --stop-datetime="2012-07-31 09:45:00" mysql-bin.941

こんな感じですね。ちなみにMySQL 4.0.x のmysqlbinlogにはstart-datetime、stop-datetimeのオプションがないので新しいバージョンが入っているサーバに転送するなりして実行しています。

この出力は

#120731 09:41:48 server id 9316  end_log_pos 798        Query   thread_id=1743530       exec_time=0     error_code=0
SET TIMESTAMP=1343394948/*!*/;
UPDATE tbl
SET    ....
WHERE  id='10756480'
/*!*/;
# at 798
#120727 09:41:48 server id 9316  end_log_pos 825        Xid = 43790241
COMMIT/*!*/;
# at 825
#120731 09:41:48 server id 9316  end_log_pos 884        Query   thread_id=1743530       exec_time=0     error_code=0
SET TIMESTAMP=1343394948/*!*/;
BEGIN
/*!*/;
# at 884

こんなフォーマットで得られます。このフォーマットだと目grepでどんなクエリが多いのか判断するのは難しいので、クエリ部分だけを抽出します。その際クエリ中の改行も消してしまいます

$ mysqlbinlog --start-datetime="2012-07-31 09:41:00" --stop-datetime="2012-07-31 09:45:00" mysql-bin.941 | perl -e 'while(<>){ chomp; next if m!^#!; if ( m{/\*!\*/;$} ) { $p .= $_; print "$p\n"; $p="" } else { $p .= $_." "} }'

すると

BEGIN /*!*/;
SET TIMESTAMP=1343394948/*!*/;
UPDATE tbl SET    ... WHERE  id='10756480' /*!*/;
COMMIT/*!*/;

こんな感じで1クエリ1行にまとまるので、目grepもしくは一つ前のエントリで紹介した「sort|uniq -c|sort -nr」などを使って集計すれば特徴的なクエリが見つけられるかもしれません。

さらに、どんなテーブルへのどの操作が多いのか調べるためにもうひとつワンライナーを組み合わせて

$ mysqlbinlog --start-datetime="2012-07-31 09:41:00" --stop-datetime="2012-07-31 09:45:00" mysql-bin.941 | perl -e 'while(<>){ chomp; next if m!^#!; if ( m{/\*!\*/;$} ) { $p .= $_; print "$p\n"; $p="" } else { $p .= $_." "} }'|perl -nle 'm!^(DELETE FROM|REPLACE INTO|INSERT INTO|UPDATE)\s+([^ ]+)!i && print "$1 $2"'
INSERT INTO tbl0
UPDATE tbl1
UPDATE tbl1
INSERT INTO tbl2
INSERT INTO tbl2
INSERT INTO tbl2
INSERT INTO tbl2
INSERT INTO tbl2
UPDATE tbl0
INSERT INTO tbl2

とすれば、操作と対象テーブルの組み合わせだけ抜き出せます。これも「sort|uniq -c|sort -nr」を使う事で

 43 INSERT INTO tbl2
 33 UPDATE tbl1
 19 INSERT INTO tbl3
 18 UPDATE tbl2
 17 INSERT INTO tbl1
 16 INSERT INTO tbl4
 11 INSERT INTO tbl5
 11 INSERT INTO tbl6
  3 INSERT INTO tbl7

このように集計が可能になりました。

ここまでくれば、対象となる時間帯にだけある特徴的な操作を見つけられるので、ソースコードから該当箇所を探しだし何かしらの手立てを考える事ができます。ここ数週間のなかで実際にいくつか無駄な処理を発見してアプリケーションを修正できたりしています。

そういえば、mk-query-digestもbinlogが喰えるようなことがドキュメントに書いてあるのですが、うまく動かないっぽいのですが、どなたか使っている方いますか?