Linuxで3万（10万）プロセスを同時に起動させてみた

といっても、きちんとした検証をしたわけではないので、あくまで「こういう環境でこういう事をやるとこうなる」という参考程度のものと理解してい頂ければ幸いです。

Linux上でプロセスは同時に何個起動できるのか

数年前にC10K問題が流行りました。これは、簡単に言うと、万のオーダーでプロセスを立ち上げる事になると、現状のOSではそれを想定した設計になっていないためまともに動かなくなる、といった問題でした。

だったら、「10万プロセス位を同時に立ち上げてみて、どうなるか試してみようぜ！」と思い、会社のエンジニアと一緒に試してみました。検証環境は、メモリ48GでCPUはHyperThreading込で24コアです。そこで動いていたOSはDebianでLinuxカーネル2.6.32だったので、とりあえずそのカーネルで試してみました。

まずは、やりたい事として、

まずは3万プロセスを同時に起動させる
それぞれのプロセス上で定期的にコンテキストスイッチや割り込みを発生させる
どういうことになるのだろうか？

ということにしました。

3万プロセスを立ち上げるための準備

そこで、簡単に以下のようなツールを作りました。

[program lang=’perl’ escaped=’true’]

#!/usr/bin/perl

while(1) {
  open $fh, '> /dev/null';
  sleep(int(rand(3)));
  print $fh "hoge";
}

[/program]

まずは、適当に3秒の範囲内でランダムの値でスリープし、定期的に/dev/nullに文字列を書き込むスクリプトを作りました。次に、以下のようなラッパースクリプトを書きました。

[program lang=’perl’ escaped=’true’]

#!/usr/bin/perl

for($i = 0; $i < 10000; $i++) {
    print "$i¥n";
    `/root/work.pl > /dev/null 2>&1 &`;
}

[/program]

sleepしながら定期的に書き込みを行うスクリプトを、1万個forkさせるように実装しました。これによって、forkされたプロセスは各自ランダムにsleepしつつ、コンテキストスイッチが定期的に発生する事になります。そして、このツールをforkしたい数だけ実行しました。今回は3万が目標なので、3回実行することになります。

また、Linuxのプロセス数の上限を増やす必要があるので、/proc/sys/kernel/pid_maxに2^22 (4194304)を書き込みました。

[program lang=’c’ escaped=’true’]

echo "4194304" > /proc/sys/kernel/pid_max

[/program]

色々試してみた結果、この値が上限のようです。

3万プロセスを立ち上げてみた

ではまず、3万プロセスを立ち上げてみました。vmstatで1秒間のコンテキストスイッチの数と割り込み回数に注目しました。

1秒間のコンテキストスイッチ数：約9万
1秒間の割り込み回数：約7万

おおよそ上記のような値になりました。メモリやCPUのリソースはまだまだスカスカでした。しかし、しばらく動かしていると、以下のようなメッセージが急に出力され出しました。

[program lang=’c’ escaped=’true’]

[Hardware Error]: No human readable MCE decoding support on this CPU type.
[Hardware Error]: Machine check events logged
[Hardware Error]: Run the message through 'mcelog --ascii' to decode.
Disabling lock debugging due to kernel taint
[Hardware Error]: No human readable MCE decoding support on this CPU type.
[Hardware Error]: Run the message through 'mcelog --ascii' to decode.
・
・
・
・

[/program]

おおー、これはなんだー。

まずは、MCE（Machine Check Excepution）について。これは、簡単に言うとx86系のCPUの自己診断機能で、ハードウェアの障害を事前に検知してくれる機能のようです。「HWの回復不能なエラーをCPUが検知する機能」なようで、はて、なんでこんなエラーが出るんだろうと疑問に思いました。

カーネルの海へ

では早速カーネルのコードリーディングに入ります。「[Hardware Error]: Machine check events logged」というログに注目して、カーネルの海に飛び込みました。今回は、前回の「Webサーバのマルチスレッドでの実装における優位性をLinux Kernel 3.3のソースから読み解く」と違ってvimとGNU GLOBALを完備している僕に死角はありません。ということで、カーネルはとりあえず3.3のカーネルを見てみてました。

すると、さっそく、/usr/local/src/linux-3.3/arch/x86/kernel/cpu/mcheck/mce.c というコードの mce_notify_irq() という関数の中に pr_info(HW_ERR “Machine check events logged\n”); という実装を見つける事ができます。GNU GLOBALであれば一瞬です。

必殺のCtrl+J！！

[program lang=’c’ escaped=’true’]

1209 int mce_notify_irq(void)
1210 {
1211     /* Not more than two messages every minute */
1212     static DEFINE_RATELIMIT_STATE(ratelimit, 60*HZ, 2);
1213
1214     clear_thread_flag(TIF_MCE_NOTIFY);
1215
1216     if (test_and_clear_bit(0, &mce_need_notify)) {
1217         /* wake processes polling /dev/mcelog */
1218         wake_up_interruptible(&mce_chrdev_wait);
1219
1220         /*
1221          * There is no risk of missing notifications because
1222          * work_pending is always cleared before the function is
1223          * executed.
1224          */
1225         if (mce_helper[0] && !work_pending(&mce_trigger_work))
1226             schedule_work(&mce_trigger_work);
1227
1228         if (__ratelimit(&ratelimit))
1229             pr_info(HW_ERR "Machine check events logged¥n");
1230
1231         return 1;
1232     }
1233     return 0;
1234 }
1235 EXPORT_SYMBOL_GPL(mce_notify_irq);

[/program]

そして、mce_notify_irq()を見ていくと、まず1212行目にDEFINE_RATELIMIT_STATE(ratelimit, 60*HZ, 2)という関数があります。この関数を見ていくと、/usr/local/src/linux-3.3/include/linux/ratelimit.h の中に定義されていることがわかります。

[program lang=’c’ escaped=’true’]

  7 #define DEFAULT_RATELIMIT_INTERVAL  (5 * HZ)
  8 #define DEFAULT_RATELIMIT_BURST     10
  9
 10 struct ratelimit_state {
 11     raw_spinlock_t  lock;       /* protect the state */
 12
 13     int     interval;
 14     int     burst;
 15     int     printed;
 16     int     missed;
 17     unsigned long   begin;
 18 };
 19
 20 #define DEFINE_RATELIMIT_STATE(name, interval_init, burst_init)     ¥
 21                                     ¥
 22     struct ratelimit_state name = {                 ¥
 23         .lock       = __RAW_SPIN_LOCK_UNLOCKED(name.lock),  ¥
 24         .interval   = interval_init,            ¥
 25         .burst      = burst_init,               ¥
 26     }

[/program]

上記コードの20行目から26行目に渡って書かれており、ratelimit_state構造体であるnameに、引数で渡したinterva_init、つまりは60*HZと、burst_init、つまりは2を代入しています。ここで、HZとはCPUが1秒間に発生するタイマ割り込みの回数で、60*HZというのは、1分間で発生するタイマ割り込みの回数になります。ここで、カーネルにおいては、様々なタイマ処理にjiffiesとよばれるグローバル変数が利用されています。jiffiesはカーネルが起動してから、発生するタイマ割り込みのタイミングでインクリメントされる変数です。このjiffiesの値を利用することで、例えば60秒という時間は、jiffiesの値が60*HZだけ増えていることで判断する事ができます。

そのような前提知識を持って、さらにソースを見ていきます。/usr/local/src/linux-3.3/arch/x86/kernel/cpu/mcheck/mce.c の mce_notify_irq()に戻って、DEFINE_RATELIMIT_STATEの続きを見ていきます。

[program lang=’c’ escaped=’true’]

1209 int mce_notify_irq(void)
1210 {
1211     /* Not more than two messages every minute */
1212     static DEFINE_RATELIMIT_STATE(ratelimit, 60*HZ, 2);
1213
1214     clear_thread_flag(TIF_MCE_NOTIFY);
1215
1216     if (test_and_clear_bit(0, &mce_need_notify)) {
1217         /* wake processes polling /dev/mcelog */
1218         wake_up_interruptible(&mce_chrdev_wait);
1219
1220         /*
1221          * There is no risk of missing notifications because
1222          * work_pending is always cleared before the function is
1223          * executed.
1224          */
1225         if (mce_helper[0] && !work_pending(&mce_trigger_work))
1226             schedule_work(&mce_trigger_work);
1227
1228         if (__ratelimit(&ratelimit))
1229             pr_info(HW_ERR "Machine check events logged¥n");
1230
1231         return 1;
1232     }
1233     return 0;
1234 }
1235 EXPORT_SYMBOL_GPL(mce_notify_irq);

[/program]

すると、1228行目の__ratelimit(&ratelimit)がtrueを返している場合に、MCEのHW_ERRのログが出力されているようです。さっそく、__ratelimit()を見ていきます。すると、/usr/local/src/linux-3.3/include/linux/ratelimit.hにおいてマクロで以下のように定義されています。

[program lang=’c’ escaped=’true’]

 42 #define __ratelimit(state) ___ratelimit(state, __func__)

[/program]

さらに、___ratelimit()を追います。/usr/local/src/linux-3.3/lib/ratelimit.cの中に___ratelimit()がありました。

[program lang=’c’ escaped=’true’]

 28 int ___ratelimit(struct ratelimit_state *rs, const char *func)
 29 {
 30     unsigned long flags;
 31     int ret;
 32
 33     if (!rs->interval)
 34         return 1;
 35
 36     /*
 37      * If we contend on this state's lock then almost
 38      * by definition we are too busy to print a message,
 39      * in addition to the one that will be printed by
 40      * the entity that is holding the lock already:
 41      */
 42     if (!raw_spin_trylock_irqsave(&rs->lock, flags))
 43         return 0;
 44
 45     if (!rs->begin)
 46         rs->begin = jiffies;
 47
 48     if (time_is_before_jiffies(rs->begin + rs->interval)) {
 49         if (rs->missed)
 50             printk(KERN_WARNING "%s: %d callbacks suppressed¥n",
 51                 func, rs->missed);
 52         rs->begin   = 0;
 53         rs->printed = 0;
 54         rs->missed  = 0;
 55     }
 56     if (rs->burst && rs->burst > rs->printed) {
 57         rs->printed++;
 58         ret = 1;
 59     } else {
 60         rs->missed++;
 61         ret = 0;
 62     }
 63     raw_spin_unlock_irqrestore(&rs->lock, flags);
 64
 65     return ret;
 66 }
 67 EXPORT_SYMBOL(___ratelimit);

[/program]

この関数がtrueを返す状況は2つあるようです。まずは、33行目でratelimit_stateのintervalが偽の場合です。しかし、これは上述したDEFINE_RATELIMIT_STATE()によって、60*HZの値だけjiffiesのタイマの単位で定義されているはずです。そのため、trueを返す状況としては、42行目から58行目の実装によるものだと考えられます。詳しく見ていきます。

[program lang=’c’ escaped=’true’]

 42     if (!raw_spin_trylock_irqsave(&rs->lock, flags))
 43         return 0;
 44
 45     if (!rs->begin)
 46         rs->begin = jiffies;
 47
 48     if (time_is_before_jiffies(rs->begin + rs->interval)) {
 49         if (rs->missed)
 50             printk(KERN_WARNING "%s: %d callbacks suppressed¥n",
 51                 func, rs->missed);
 52         rs->begin   = 0;
 53         rs->printed = 0;
 54         rs->missed  = 0;
 55     }
 56     if (rs->burst && rs->burst > rs->printed) {
 57         rs->printed++;
 58         ret = 1;
 59     } else {
 60         rs->missed++;
 61         ret = 0;
 62     }

[/program]

まず、rs->beginは初期化時に0が代入されているため、現状のjiffiesの値が入ります。そして、数万プロセスがforkされ大量のコンテキストスイッチや割り込み処理が発生している状況で、48行目によってbeginに代入時のjiffiesの値＋60*HZの値を、time_is_before_jiffies(rs->begin + rs->interval)によって評価します。この関数を見ていきます。/usr/local/src/linux-3.3/include/linux/jiffies.hでマクロとして以下のように定義されています。

[program lang=’c’ escaped=’true’]

151 /* time_is_before_jiffies(a) return true if a is before jiffies */
152 #define time_is_before_jiffies(a) time_after(jiffies, a)

[/program]

さらに、time_after(jiffies, a)を見ていくと、同じ/usr/local/src/linux-3.3/include/linux/jiffies.hで以下のようにマクロで定義されているようです。

[program lang=’c’ escaped=’true’]

106 #define time_after(a,b)     ¥
107     (typecheck(unsigned long, a) && ¥
108      typecheck(unsigned long, b) && ¥
109      ((long)(b) - (long)(a) < 0))

[/program]

つまり、time_is_before_jiffies(rs->begin + rs->interval)は現在のjiffiesの値より、rs->beginに入れた時のjiffiesの値と60*HZしたタイマ割り込み数を足した値が少ない場合にtrueが返る事がわかります。その場合は、rs->begin、rs->printedにそれぞれ0が代入されます。そして、56行目のif (rs->burst && rs->burst > rs->printed)において、rs->burstは上述したDEFINE_RATELIMIT_STATE()において2が代入されているため真となり、返り値であるretに1が入ります。そして、最後にもう一度mce_notify_irq()のコードを以下に示します。

[program lang=’c’ escaped=’true’]

1209 int mce_notify_irq(void)
1210 {
1211     /* Not more than two messages every minute */
1212     static DEFINE_RATELIMIT_STATE(ratelimit, 60*HZ, 2);
1213
1214     clear_thread_flag(TIF_MCE_NOTIFY);
1215
1216     if (test_and_clear_bit(0, &mce_need_notify)) {
1217         /* wake processes polling /dev/mcelog */
1218         wake_up_interruptible(&mce_chrdev_wait);
1219
1220         /*
1221          * There is no risk of missing notifications because
1222          * work_pending is always cleared before the function is
1223          * executed.
1224          */
1225         if (mce_helper[0] && !work_pending(&mce_trigger_work))
1226             schedule_work(&mce_trigger_work);
1227
1228         if (__ratelimit(&ratelimit))
1229             pr_info(HW_ERR "Machine check events logged¥n");
1230
1231         return 1;
1232     }
1233     return 0;
1234 }
1235 EXPORT_SYMBOL_GPL(mce_notify_irq);

[/program]

上記から、1228行目の__ratelimit()はtrueとなり、エラーログが出力されるわけです。

考察

このように、万のオーダーでプロセスを生成して数万のコンテキストスイッチや割り込み処理を発生させると、リソースの空き状況によらず以下のような問題が発生する事がわかりました。

Machine Check ExceptionによってCPU自己診断機能がエラーを出す
エラー内容はCPUが割り込み待ちに60秒以上かかってしまう状況が発生？
恐らくCPUのBUSY状態が長すぎる事を示すエラー

というような予想がつきます。誰かこの詳細が分かる方はいらっしゃいますか？是非ともご教授頂けるとうれしいです。

他の実装を見ていくと、この状況になった場合は/usr/local/src/linux-3.3/include/linux/ratelimit.h の中に定義されているデフォルトのratelimitのintervalやbusrt値に置き換えて再チェックしていく実装になっている事がわかりました。

[program lang=’c’ escaped=’true’]

  7 #define DEFAULT_RATELIMIT_INTERVAL  (5 * HZ)
  8 #define DEFAULT_RATELIMIT_BURST     10

[/program]

まず、この状況がどれほどまずいのかが分かっていません。とりあえず、MCEがエラーを出しているんだから良くない事が起きているんだとは予想できます。しかし、この状況で他のプロセスを立ち上げたり処理したりしても、特にOS上でおかしな事が起きているようにも思えませんでした。

とりあえずの結論として、万のオーダーでプロセスを立ち上げる用途では、インターバルの値をもっと長くしてあげる必要があるのかもしれませんが、全く自信はありません。MCEが反応しだしたということは、「僕はCPUですが、割り込みとかコンテキストスイッチ多過ぎでもう無理っす」というメッセージなのだろうか。の割には、レスポンスは結構ぴんぴんしていました。

ちなみに

sleepしてwriteするプロセスをC言語で実装すると、10万プロセス以上を同時に実行できて、1秒間のコンテキストスイッチ数を15万、1秒間の割り込み数を7万、にしても上記のエラーはでませんでしたし、結構さくさく動いていました。プロセス単位でのリソースも関連しているのかもしれませんね。

フォローアップ（追記：2012年5月17日22時）

twitterの皆様に色々と感想やご指摘を頂いて、非常に参考になるものばかりでしたので、上記のmceの挙動について現状の解釈を追記します。

まずは、きっかけとして＠madogiwa さんの指摘がズバリだと思いました。

60秒なのは表示の抑制だけで、エラー(mce_need_notifyに値がセット)は別条件な感じにも見えるような。 / 人間とウェブの未来 – Linuxで3万（10万）プロセスを同時に起動させてみた blog.matsumoto-r.jp/?p=2545

— madogiwaさん (@madogiwa) 5月 16, 2012

そして、今日は大学で色々研究室の事をやっている間になされていた＠shmorimo さんの解釈が非常に参考になりました。

あー違う ratelimit に来た時点で、エラーだよってことなのでもっと上を見ないと。ratelimit はログ出力のrateの調整だけ？

— Shigeki Morimotoさん (@shmorimo) 5月 17, 2012

そうですね、確かにratelimitに来た時点でmissedになろうとprintedになろうといずれかのエラーが出力されてしまいます。

エラーがあると誰かが mce_need_notify を立てて、test_and_clear_bit(0, &mce_need_notify) が真になってログがでるので、このフラグを立てる人を探す必要があるのかな。

— Shigeki Morimotoさん (@shmorimo) 5月 17, 2012

非常に分かりやすい！これを聞いてコードを読むと、まさのそのとおりだと思いました。で、結局大元のエラー出力の関数を調べていくと以下のようにmce_log()にたどり着きます。

mce_log()が呼ばれる条件を調べる必要があるみたい-人間とウェブの未来 – Linuxで3万（10万）プロセスを同時に起動させてみた blog.matsumoto-r.jp/?p=2545

— Shigeki Morimotoさん (@shmorimo) 5月 17, 2012

で、最終的にはkernelがエラーを検知するのではなく、CPUの機構で検知しているように思われます。

@matsumotory CPUがエラーを検知するとどこか（CPU内？）にログを書き込み、それを割り込みで通知してきて最終的にmce_log()が呼ばれるようです。カーネルではエラーの検知はしてないようです。実際のエラーを見るには mcelog –ascii しかないかも。

— Shigeki Morimotoさん (@shmorimo) 5月 17, 2012

ということで、カーネルのレイヤーでは分かるのはここまでで、MCEやIntel CPUのドキュメントを見ていく必要がありそうです。

ちなみに、そういう調査も含めて今後は以下のような観点でも検証していきたいと考えています。

@shmorimo マルチプロセスだとコンテキストスイッチ毎にTLBがフラッシュされるのも、あれ程のプロセス数だとCPUにどういう影響与えるのか、を含めておってみたいと思っています。

— MATSUMOTO, Ryosukeさん (@matsumotory) 5月 17, 2012

続きやりましょう。各プロセスでTCPコネクションもはらせたいですね。となるとfdやらソケットI/Oの問題とか色々でてきそうですけど。 RT @WhiteAnthrax: @matsumotory あ。すっかり忘れてた

— MATSUMOTO, Ryosukeさん (@matsumotory) 5月 17, 2012

以上、簡単ではありますが、今回のmce_notify_irq()周りの解釈はこの程度に留めておこうと思います。皆様ありがとうございました！

「Linuxで3万（10万）プロセスを同時に起動させてみた」への3件のフィードバック

shmorimo

2012年5月17日 6:34 PM

ratelimit はログを1分間に2回に抑えるためのロジックに思えます。
どこかでエラーが検知されると mce_need_notify が1に設定されて
”Machine check events logged”
のログが出力されるのかと。

でもmce_need_notify を1にする処理が見つからない…
shmorimo

2012年5月17日 6:55 PM

見落としてました mce_log()が呼ばれるとフラグがたちますね。
と、いうことで、mce_log()が呼ばれる条件を追うのがよさそうです。
matsumoto_r (MATSUMOTO Ryosuke)

2012年5月17日 10:00 PM

>> shmoromoさん
twitterでは、ありがとうございました。僕自身が完全にわかっているわけではないので断言はできませんが、shmorimoさんの解釈で正しいと思われます。
本エントリに引用させて頂きますね。今後とも、間違いなどありましたらご指摘して頂けると幸いです！

コメントは受け付けていません。