酒日記 はてな支店

■[perl] warn() で吐かれるログを捕まえて投げる

Perl では $SIG{__WARN__} という疑似シグナルハンドラを使って、warn() で出力されようとする内容をトラップして処理することができます。

package MyWorker;

my $logger = Fluent::Logger->new;

sub work {
    my $job = shift;

    local $SIG{__WARN__} = sub {
        my $msg = shift;   # warn() で出力される文字列が渡ってくるので logger で送る
        $logger->post(
            "job" => {
                 jobid   => $job->jobid,   # jobid で検索できるように
                 message => $msg,
             },
        );
    };

    # job の処理
    # warn("Error!")
}

最初からログを何らかのオブジェクトに渡す仕組みを入れて作っていればよかったのですが、経緯としては以下のような歴史がありまして…

• 昔とある job 処理をする worker がおり
• そいつは全くログを吐いておらず
• つまり処理途中で何がおきて失敗したのか分からず
• 手っ取り早く warn() で処理の途中経過を吐き出すように修正
• 結果、そこから呼び出されるコードのあちこちに warn() が埋め込まれてしまい

あとから $logger オブジェクトを渡そうにも、そのようなインターフェースがないという状態に。

仕方ないのでこのような手法をとった次第。

Permalink | コメント(0) | トラックバック(0) | 19:03

■[perl] Perl から Fluentd にログ出力 - Fluent::Logger リリース

皆さん、ログ書いてますか！？(挨拶)

Fluentd meetup in Japan も開催間近、最近大変熱いイベントログ収集システム Fluentd なわけですが、Perl からログを出力する Fluent::Logger というモジュールを CPAN にリリースしたのでお知らせします。

(最初の版は id:hirose31 さんが書かれて、それに同僚の id:shin1rosei と手を加えたものです)

インストールは cpanm などでどうぞ。使い方は POD にもあるように簡単です。

use Fluent::Logger;
my $logger = Fluent::Logger->new( host => "127.0.0.1", port => 24224 );
$logger->post( "myapp.info" => { foo => "bar" } );

上記の例で送信するメッセージ { foo => "bar" } の部分は、Fluentd の特徴である構造化されたメッセージを任意の hashref で指定できます。

ログを送信しようとして fluentd に繋がらない場合、接続が切断されていた場合にはオブジェクト内のバッファにメッセージを保存し、再接続、再送する機能もあります。接続を永続化した状態で fluentd を再起動しても安心です。

ただしオブジェクトが消滅するタイミングまでに fluentd に送信できなかった場合は、バッファをメモリ上に持っているため当然ながらメッセージが失われてしまいます。本番環境では

• Fluent::Logger オブジェクトを永続化する
• 中継用に disk バッファを持つ fluentd を配置する

などの構成をおすすめします。

パフォーマンスについて

リポジトリ内に簡単なベンチマークスクリプト xt/06_benchmark.t があります。手元の macbook Air (13" late 2010) に、fluentd-0.10.8 を同一ホストに立てた状態で以下のような結果です。

# 0.63 sec / 10000 msgs (37 bytes) = 15757.09qps (4.45Mbps)
# 0.67 sec / 10000 msgs (129 bytes) = 14910.66qps (14.67Mbps)
# 0.91 sec / 10000 msgs (1029 bytes) = 11014.97qps (86.47Mbps)

メッセージ長に左右されますが、1万qps 以上。オリジナルの Ruby 版には若干及びませんが、実用上十分な速度だと思います。

要望、フィードバックなどありましたらお寄せください。github リポジトリはこちらです https://github.com/fluent/fluent-logger-perl

Permalink | コメント(0) | トラックバック(0) | 10:34

■ KVM guest VM が突然 paused になった

何も前触れもなく、KVM の guest VM が突然 paused (suspend した状態) になってしまって何事かなのか悩んでいたところ。

まさしく、DISK image を置いていたパーティションが 100% になっていました。sparse で作成していたので、容量分のファイルは作成できていたのだけど、実際に確保するところで足りなくなった状態でした。

他のパーティションに mv して事なきを得ましたが、実際以上に容量確保できる sparse image を実運用するときは要注意ですね……

Permalink | コメント(0) | トラックバック(0) | 02:40

■[mysql] クエリキャッシュを切ったほうがいイカ？ ベンチマークしてみた

カジュアル！(挨拶)

このエントリは MySQL Casual Advent Calendar 2011 の18日目の記事です。

昔、専ら PostgreSQL を使っていた頃、MySQL のクエリキャッシュって簡単に性能上がるしみたいだし羨ましいなあ、と思っていました。そのため、1年ほど前から業務で MySQL を使うようになっても、クエリキャッシュは当然のごとく有効にしておりました。

ところが先日 DSAS開発者の部屋:クエリキャッシュは切ったほうがいいんじゃなイカ？ というエントリを読みまして、クエリキャッシュはグローバルロックを獲得するとのこと。これはちょっと検証してみなければなるまい、ということでベンチマークをしてみました。

ベンチマーク結果

• 結果は別ページにまとめました
• benchmark script と my.cnf

ざっくりと説明しますと、

• 平均 260 byte/行、100万行の InnoDB テーブルに対して
• 主キーによる 1行 select、セカンダリインデックスによる平均16行の select (light query)
• 上記に10%の割合で、セカンダリインデックスでの 6万行 count(*) を混ぜる (heavy query)

を実行した場合の qps (query per second) をスコアとします。ちなみに InnoDB buffer pool 2GB で、データは全て buffer pool に乗り切っている状態です。

パラメータは以下です。

• クエリキャッシュ : 有効 | 無効
• クライアント数 : 4 | 8 | 16 | 32 | 64
• 同時にテーブルに更新 : 掛けない | 0.1秒ごとに1行update

考察

結果を見ていきます。

インデックスを使って少数の行を select するだけの場合。(light query)

クエリキャッシュ有効でテーブルに更新がない場合、並列度を上げていっても性能が伸びません。32, 64並列では無効の場合は 10,000 qps 程度、有効だと 5,000 qps に達せず半分以下のスコアです。

有効で並列度を上げたベンチマーク中に SHOW PROCESSLIST を見えると、State が "Waiting for query cache lock" となっている行が大量に存在していました。

ただし、有効の場合でも、0.1秒ごとに update を掛けるとスコアが上がっています。

次に、row examined 60000 程度の重い集約クエリを混ぜた場合。(heavy query)

クエリが重いため、更新がなければキャッシュが有効に作用し、スコアが上がります。ただし、当然ですが更新を同時に掛けるとキャッシュにほとんどヒットしなくなるため、無効の時と同等になってしまいます。

結論

ということで、クエリキャッシュを有効にしているとかえって性能が落ちることがある、という結論です。

もちろんユースケースによって、あまり更新の掛からない DB に重いクエリを投げるような場合には効果的に作用することはあると思います。

さて、この結果を踏まえて、とある実運用中の DB をクエリキャッシュ有効から無効に変更してみました。比較的更新の多い使いかたです。

• select 1000qps, insert 100qps, update 300qps
• クエリキャッシュヒット率 50% 程度
• データは全て InnoDB buffer pool に乗るサイズ

クエリキャッシュを無効にしたところ、

• CPU (user) 使用率が 2/3 に低下 (3%→2%、程度ですが…)
• Threads_running が平常時 1〜2程度なのに時折 50程度に跳ね上がる現象が解消

という改善が得られました。

また、slow query log に通常時は数msecで結果の返るクエリが、以下のように 100msec 程度掛かっているという不審な現象が出ていました。これがクエリキャッシュを無効にしたところぱったりと止みました。

Query_time: 0.102920  Lock_time: 0.050687

特定テーブルでもなく、特定クエリでもなく、しかも計ったように Query_time: 0.1+α, Lock_time: 0.05+α という非常に気持ち悪い (上に 100ms も掛かるので性能的に大問題) な現象だったのですが、まさかクエリキャッシュを無効にして直るとは。

明日は @n0ts さんです！

Permalink | コメント(0) | トラックバック(1) | 11:26

■ HAProxy で graceful restart する方法

haproxy には起動後に設定ファイルを読み込み直したりする機能がないので、バランス先を追加するなどの変更が無停止ではできない、と思い込んでいたのだけど実は違った、というお話。

実際、同一プロセスで読み込み直すことはできないのだけども、以下のような手法で graceful に再起動することができる。man はちゃんと読みましょう。

# haproxy -f /path/to/haproxy.conf -sf [既に動いているhaproxyのpid]

として -sf オプションに pid を渡して起動すると……

• haproxy[2] : 起動
• haproxy[2] : 既に動いている haproxy[1] に SIGTTOU を送信
• haproxy[1] : SIGTTOU を受けると Listen をやめる
  • 新規接続は受け付けない
  • 既に確立している接続はそのまま維持
• haproxy[2] : socket を Listen し、新しい接続を受け入れる状態に
• haproxy[2] : haproxy[1] に SIGUSR1 を送信
• haproxy[1] : SIGUSR1 を受けると、既存の接続が全て終了するのを待って停止 (graceful shutdown)

これで既存の接続を落とすことなく、新しい設定で起動した haproxy に動作を引き継ぐことができます。賢いですね。

ちなみに自分のところでは daemontools から起動していたのだけど、これだと上記の手法が使いづらい。別プロセスとして起動して、一時的には平行して 2プロセスが動作する必要があるため。

contrib から init script を貰ってきて、それから起動するように変更。

この変更も無停止でなんとか。

# svstat /service/haproxy                     # pidを調べる
# echo $HAPROXY_PID > /var/run/haproxy.pid    # pidファイル作成
# mv /service/haproxy /service/.haproxy       # daemontools から起動しないように
# svc -x /service/.haproxy
# service haproxy reload                      # reload で -sf オプション付き起動
# rm /service/.haproxy

ということで、設定変更に再起動が必要なのがちょっと不便……というのは勘違いでした。これでより安心してバリバリ使えますね！

Permalink | コメント(0) | トラックバック(0) | 22:30