2013-02-01
■ MongoDBをNUMAなマシンで使うときの注意
デュアルCPUで計12コア24スレッド、メモリ48GBというマシンで MongoDB-2.0.8 をしばらく稼働させたところ、突然 CPU の system time が1コア分暴走したようになる、という現象が起きました。
最初は原因がよく分からず、とりあえず mongod のプロセスを kill して起動し直したら復旧したのですが、またしばらくすると同じ現象に。
mongoのメモリ使用量と Load Average をプロットしてみると、どうもある程度 (約24GB?) のメモリを使ったところで暴走が起きているような……とログを見直してみると、起動時に WARNING がでていました。
Sun Jan 20 00:10:01 [initandlisten] MongoDB starting : pid=12669 port=27017 dbpath=/var/lib/mongo 64-bit host=mng-log04 Sun Jan 20 00:10:01 [initandlisten] Sun Jan 20 00:10:01 [initandlisten] ** WARNING: You are running on a NUMA machine. Sun Jan 20 00:10:01 [initandlisten] ** We suggest launching mongod like this to avoid performance problems: Sun Jan 20 00:10:01 [initandlisten] ** numactl --interleave=all mongod [other options] Sun Jan 20 00:10:01 [initandlisten] Sun Jan 20 00:10:01 [initandlisten] ** WARNING: /proc/sys/vm/zone_reclaim_mode is 1 Sun Jan 20 00:10:01 [initandlisten] ** We suggest setting it to 0 Sun Jan 20 00:10:01 [initandlisten] ** http://www.kernel.org/doc/Documentation/sysctl/vm.txt Sun Jan 20 00:10:01 [initandlisten] Sun Jan 20 00:10:01 [initandlisten] db version v2.0.8, pdfile version 4.5 Sun Jan 20 00:10:01 [initandlisten] git version: a340a57af7cdda865da420704e1d1b2fac0cedc2
本家のドキュメントにも書いてありました。MongoDB on NUMA Hardware
NUMAのハードウェアで動かす場合は以下の通り設定せよ、とのこと。
- numactl --interleave=all mongod [オプション] で起動する
- /proc/sys/vm/zone_reclaim_mode を 0 にする
この設定をして起動したところ、メモリ使用量が29GBを超えても今のところ問題ないようです。2 CPUで 48GBなので、暴走する閾値の24GBというのは 1 CPU 分のメモリでしょうかね。
Permalink | コメント(2) | トラックバック(0) | 13:34 
2013-01-25
■ 異常値検出プラグイン fluent-plugin-anomalydetect を使ってみたのでそろそろ閾値を決めたい
異常値検知、素敵な響きですね！fluent-plugin-anomalydetect 作りました - PolyPeaceLight
あらかじめ固定値でアラートの条件を決めておかなくても、通常と異なる数値変化を検出してアラートできたら大変嬉しい、ということでインストールして一週間ほど運用してみました。
- fluent-agent-lite で送信されてくる nginx のアクセスログの数を対象
- 60秒間隔で集計
<match nginx.access.**>
type copy
<store>
...
</store>
<store>
...
</store>
<store>
type anomalydetect
tag nginx.anomaly.access_log
tick 60
store_file /var/log/td-agent/anomalydetect.dat
</store>
</match>
目論見としては、アクセス数の急変 (増加、減少) を検知したい、というところです。
nginx.anomaly.access_log {"outlier":17.139157711554112,"score":7.503651241329008,"target":2367} nginx.anomaly.access_log {"outlier":7.1147699712708645,"score":3.0314162920326417,"target":2391} nginx.anomaly.access_log {"outlier":7.1296905023335135,"score":3.4056734467047143,"target":2502}
このようなログが60秒ごとに出力されるので、scoreの値を zabbix に送ってグラフにして観察してみます。
実際にアクセス数が急変した状態でのグラフを並べてみると…
19:41ごろの急上昇に対応してスコアが上がり、最大で 4.35 になりました。ただ、19:00ごろの小さなピークに対する反応 (スコア 2.62) と比べると、スコア的な差が小さく感じます。
デフォルトの状態では起動直後はスコアが7程度、それから時間が経過すると低下していき、平常時は 0〜3 程度の値を取るようです。特に大きな変化のない状態で、1日分をグラフにすると以下のような感じです。
急激なダウンについてはまだ幸いにも大きな障害が起きていないため、スコアがどのような反応をするのか、引き続き観察してアラートに使用する score の閾値を決めたいですね。
Permalink | コメント(0) | トラックバック(0) | 16:28
2012-12-21
■ RSS対応NICなのに割り込み処理が複数コアに分散しない…のはirqbalanceが動いてなかったから
タイトルがすべてでございます。
NICの割り込み処理が1コアに集中してしまい、ボトルネックになって性能が出ない場合があるという話は最近広く知られていると思います。
NICのハードウェアレベルで割り込みを分散してくれる RSS(Receive Side Scaling) という仕組みがあり、それを利用すれば特になにもしなくても複数コアに分散されるはず、と思っていたのですが、どうも特定のマシンでそうならない。
# cat /proc/interrupts
CPU0 CPU1 CPU2 (省略) CPU11
64: 1256214 0 0 ... 0 IR-PCI-MSI-edge eth1-0
65: 225711 0 0 0 IR-PCI-MSI-edge eth1-1
66: 402906 0 0 0 IR-PCI-MSI-edge eth1-2
67: 723539 0 0 0 IR-PCI-MSI-edge eth1-3
68: 239176 0 0 0 IR-PCI-MSI-edge eth1-4
69: 726571 0 0 0 IR-PCI-MSI-edge eth1-5
70: 1957739 0 0 0 IR-PCI-MSI-edge eth1-6
71: 2278926 0 0 0 IR-PCI-MSI-edge eth1-7
NIC は BCM 5709 なので RSS 対応しているはずで、eth1-0 〜 eth1-7 まで8つのqueueがあるのは見えています。
なぜだ！と思って分散されているホストとそうでないホストで設定を見比べたところ、単に irqbalance が動いていなかった（インストールすらされていなかった）というオチでした。
# yum -y install irqbalance # service irqbalance start # chkconfig irqbalance on
irqbalance をインストールして起動したところ、無事複数コアに分散するようになりました。
Scientific Linux 6.3 を最小構成でインストールすると入らないんでしょうか…いや、それ最小すぎるだろう…
【追記】irqbalanceを動かすことで分散されるように設定されますが、必須ではないそうです。id:syuu1228 さんありがとうございます。(コメント欄参照)
RSS非対応なNICでもソフトウェア的に割り込みを分散させる方法については、以下のエントリが参考になります。
- CentOS 6.2 で RPS/RFS を使ってネットワークの割り込み処理を複数コアに分散してみた - blog.nomadscafe.jp
- CentOS5でもRPS/RFSでNICが捗る話 - nekoya press
Permalink | コメント(3) | トラックバック(0) | 19:07
2012-12-05
■ Redisでログの書き込みがblockを引き起こす
「RedisかわいいよRedis」(by typester)……というほど自分は Redis 期でもないのですが、最近 Redis を使ったサービスの面倒を見ていて時々レスポンスが悪化する現象に出会ったので調べました。
前提
使用しているのは Redis 2.4.16 です。
redis.conf に "save [t] [n]" を定義すると、最後に save をしてから [t]秒間に [n]個以上の key が更新された場合に background で save (=bgsave) が実行されます。
save 60 10000
これだと、60秒間に 10,000 keys です。
bgsave では redisは自分自身のプロセスを fork() し、子プロセス側は自分のメモリに乗っている内容をファイルにすべて書き出します。
この仕組みによって、1プロセス 1スレッドで動作している redis の操作を block することなしに全データのファイルへの書き込みを実現しています。賢いですね。
発生した問題
redisにアクセスしている webアプリケーションのレスポンスタイムが悪化し、数秒 block するような挙動が見られました。この挙動は、bgsave 実行中に発生しています。
原因の特定
仮に redis が持っているデータが 4GB だったとすると、bgsave するときには 4GB まるごとのファイル書き込みが発生します。
親の redis プロセスはファイル書き込みをしないので DISK IO が多くても問題ない……かと思いきや、設定によっては直接ログファイルを書き込むことがあります。
loglevel verbose logfile /var/log/redis.log
[3886] 05 Dec 14:13:42 - Accepted 127.0.0.1:36837 [3886] 05 Dec 14:13:42 - Client closed connection [3886] 05 Dec 14:13:43 - Accepted 127.0.0.1:36838 [3886] 05 Dec 14:13:43 - Client closed connection
どうやら bgsave が走って大量の DISK IO が起きているタイミングでログを書き込むとそこで block するらしい、ということを突き止めました。
特定方法
strace で redis のプロセスが発行する syscall を抽出し、以下の Perl script でタイムスタンプが 0.2 秒以上間隔が空いた前後を出力したところ、write() のあとの close() で数秒掛かることがあるのを発見。ちなみにソースを読むと分かりますが、redis.c 内の redisLog() で、ログ出力ごとにファイルを追記モードで fopen(), fprintf(), fclose() しています。
# strace -ttt -p `pgrep redis` 2>&1 | perl timegap.pl Wed Dec 5 10:10:29 2012 1354669829.089764 write(52, "[2255] 05 Dec 10:10:29 - Client "..., 50) = 50 Wed Dec 5 10:10:34 2012 1354669834.418856 close(52) = 0 Wed Dec 5 10:11:55 2012 1354669915.735166 write(55, "[2255] 05 Dec 10:11:55 - Accepte"..., 50) = 50 Wed Dec 5 10:11:57 2012 1354669917.761811 close(55) = 0
#!/usr/bin/env perl use strict; my $prev_ts = 0; my $prev_line = ""; $| = 1; while (my $line = <>) { chomp $line; my ($ts, $log) = split / /, $line, 2; if ($prev_ts && $ts - $prev_ts > 0.2) { printf "%s %s\n", scalar localtime($prev_ts), $prev_line; printf "%s %s\n", scalar localtime($ts), $line; } $prev_ts = $ts; $prev_line = $line; }
対応
loglevel verbose ではクライアントが接続、切断するごとにログに記録されますが、ヘルスチェックのために毎秒接続・切断をしているのでログファイルへの書き込みも毎秒発生していました。
loglevel notice に変更し、ログ出力を抑制したところ bgsave 時にブロックされる現象がなくなりました。
根本的には、redis がログを直接ファイルに出力するのではなく、標準出力経由で multilog に渡す、syslogに投げるなどに変更するのが better でしょうか。神の書がほしいです。
(変更前後のアプリケーションのレスポンスタイム統計)
Permalink | コメント(0) | トラックバック(0) | 14:39
2012-11-22
■ [fluentd] 同じメッセージを間引く fluent-plugin-suppress を書いた
fluentdで、なんらかの理由で大量に同じメッセージが送信されてきたときに、それを渡す output plugin によってはちょっと困ることがあります。たとえば out_mail を使うとメールが大量に飛んでしまう。
ということで、同じ (指定したkeyの値を連結したものが同じ) メッセージを適当に間引いてくれるプラグインを書きました。
- fujiwara/fluent-plugin-suppress ? GitHub
- fluent-plugin-suppress | RubyGems.org | your community gem host
使いかた
<match foo.**> type suppress interval 10 num 2 attr_keys host,message add_tag_prefix sp. </match>
[interval] 秒間に [num] メッセージはタグが書き換わって再 emit され、それを超えた分は捨てられます。「同じメッセージ」の判断は、tag と attr_keys で指定したカラムの値を "\0" で連結した文字列で行われます。
入力例
2012-11-22T11:22:33 foo.info {"id":1,"host":"web01","message":"error!!"}
2012-11-22T11:22:34 foo.info {"id":2,"host":"web01","message":"error!!"}
* 2012-11-22T11:22:35 foo.info {"id":3,"host":"web01","message":"error!!"}
* 2012-11-22T11:22:36 foo.info {"id":4,"host":"web01","message":"error!!"}
2012-11-22T11:22:37 foo.info {"id":5,"host":"app01","message":"error!!"}
* 2012-11-22T11:22:38 foo.info {"id":6,"host":"web01","message":"error!!"}
* 2012-11-22T11:22:39 foo.info {"id":7,"host":"web01","message":"error!!"}
* 2012-11-22T11:22:40 foo.info {"id":8,"host":"web01","message":"error!!"}
2012-11-22T11:22:45 foo.info {"id":9,"host":"web01","message":"error!!"}
(* = 間引かれるメッセージ)
出力例
2012-11-22T11:22:33 sp.foo.info {"id":1,"host":"web01","message":"error!!"}
2012-11-22T11:22:34 sp.foo.info {"id":2,"host":"web01","message":"error!!"}
2012-11-22T11:22:37 sp.foo.info {"id":5,"host":"app01","message":"error!!"}
2012-11-22T11:22:45 sp.foo.info {"id":9,"host":"web01","message":"error!!"}
この例だと、10秒間の間に "host": "web01", "message":"error!!" のメッセージは2つのみ通過、id:3,4,5,6,7,8 は捨てられます。id:9 は10秒以上経過しているので通過。id:5 は "host":"app01" なので(別のメッセージなので) 通過します。
通知など、用途によっては便利かもしれませんね！
Permalink | コメント(0) | トラックバック(1) | 16:58
