ruby のスレッドのコンテキストスイッチがおもくて sleep 時間以上の wait タイムが発生する件 (Fluentd で起きる）

test-thread.rb

# Rerequisites:
# gem install ruby-prof
# 1600 threads

MODE = ARGV.shift || 'PROCESS_TIME'
require 'ruby-prof'
RubyProf.measure_mode = eval("RubyProf::#{MODE}")
RubyProf.start

threads = (1..1600).map {|i|
  Thread.new {
    loop {
      sleep 0.1
    }
  }
}
trap(:INT) {
  threads.each {|t| t.kill }
}
threads.each {|t| t.join }

result = RubyProf.stop
RubyProf::FlatPrinter.new(result).print(STDOUT)

1600 スレッドで実行するとこうなる (一部のみ抜粋)

5s ぐらいだから sleep が 50 回よばれていていいはずなのに、17回しか呼ばれていない．

Thread ID: 88206400
Fiber ID: 88559510
Total: 5.285756
Sort by: self_time

 %self      total      self      wait     child     calls  name
  0.04      5.281     0.002     0.000     5.279        1   Kernel#loop
  0.02      5.279     0.001     5.277     0.000       17   Kernel#sleep
  0.00      5.286     0.000     0.005     5.281        1   Global#[No method]

* indicates recursively called methods
Thread ID: 88206680
Fiber ID: 88559500
Total: 5.031669
Sort by: self_time

 %self      total      self      wait     child     calls  name
  0.04      5.026     0.002     0.000     5.024        1   Kernel#loop
  0.02      5.024     0.001     5.023     0.000       14   Kernel#sleep
  0.00      5.032     0.000     0.005     5.026        1   Global#[No method]

なお、1600 じゃなくて 160 スレッドぐらいだと wait は小さくなる。６秒ちょい実行していたので、sleep の呼び出し回数も大体あってる。

Thread ID: 86219580
Fiber ID: 86218850
Total: 0.030713
Sort by: self_time

 %self      total      self      wait     child     calls  name
  4.54      0.030     0.001     0.028     0.000       67   Kernel#sleep
  2.53      0.031     0.001     0.000     0.030        1   Kernel#loop
  0.03      0.031     0.000     0.000     0.031        1   Global#[No method]

何スレッドぐらいが許容範囲なのだろうか？？

コンテキストスイッチを可視化するプロファイリングツールが欲しい。指定 Thread ID のスレッドがコンテキストスイッチを受け取った時間の一覧とか。

sleep 時間が小さいとその分多くの context switch を要求するので、スレッド切り替えで詰まることが多くなりそう。sleep 時間をもっと大きくできないか考えてみるとよさそう。> fluentd プラグイン

追記: 念のため確認してみた。1600 threads で sleep 1.0 に変更してみた結果。6秒はかって sleep が６回呼ばれているのでよくなってそう。まだ wait 時間 2s あるけどマシにはなってる。

 %self      total      self      wait     child     calls  name
  0.04      2.120     0.001     0.000     2.119        1   Kernel#loop
  0.02      2.119     0.000     2.118     0.000        6   Kernel#sleep
  0.01      2.123     0.000     0.004     2.120        1   Global#[No method]

なお、この現象が発生すると CPU 使用率も I/O 負荷も低いのに、性能が頭打つ、という状況になる。はず。

環境情報

$ uname -a
Linux 2.6.32-220.17.1.el6.x86_64 #1 SMP Tue Mar 26 19:51:56 JST 2013 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/redhat-release 
CentOS release 6.2 (Final)
$ /usr/lib64/fluent/ruby/bin/ruby -v
ruby 2.1.1p76 (2014-02-24 revision 45161) [x86_64-linux]

% uname -a
Linux SVP1121A2J 3.13.0-32-generic #57-Ubuntu SMP Tue Jul 15 03:51:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
% cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=14.04
DISTRIB_CODENAME=trusty
DISTRIB_DESCRIPTION="Ubuntu 14.04.1 LTS"
% ruby -v
ruby 2.0.0p353 (2013-11-22 revision 43784) [x86_64-linux]

の環境でも似たような感じの挙動を観測できます

strace ruby test-thread.rb ってすると

…前略…
clone(child_stack=0x7f67f7bc6fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f67f7bc79d0, tls=0x7f67f7bc7700, child_tidptr=0x7f67f7bc79d0) = 24846
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 554900221}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555037318}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555063603}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555187238}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555213382}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555337626}) = 0
rt_sigaction(SIGINT, {0x7f693efbe8c0, [], SA_RESTORER|SA_SIGINFO, 0x7f693ea8f340}, {0x7f693efbe8c0, [], SA_RESTORER|SA_SIGINFO, 0x7f693ea8f340}, 8) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555479249}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555609648}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555736171}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 555875045}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {13, 556005053}) = 0
futex(0x7f6940803f64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f6940803f60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f6940803f30, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f6940804654, FUTEX_WAIT_PRIVATE, 1, NULL

ここで止まる。

ruby-prof をはずしてみる。16000 スレッドにしてみると、puts が１秒に１０回されない。

#MODE = ARGV.shift || 'PROCESS_TIME'
#require 'ruby-prof'
#RubyProf.measure_mode = eval("RubyProf::#{MODE}")
#RubyProf.start

thread1 = Thread.new {
  loop {
    puts Time.now
    sleep 0.1
  }
}
threads = (1..16000).map {|i|
  Thread.new {
    loop {
      sleep 0.1
    }
  }
}
trap(:INT) {
  threads.each {|t| t.kill }
  thread1.kill
}
threads.each {|t| t.join }
thread1.join

#result = RubyProf.stop
#RubyProf::FlatPrinter.new(result).print(STDOUT)

出力

2014-08-05 14:12:46 +0900
2014-08-05 14:12:46 +0900
2014-08-05 14:12:47 +0900
2014-08-05 14:12:47 +0900
2014-08-05 14:12:47 +0900
2014-08-05 14:12:48 +0900
2014-08-05 14:12:48 +0900
2014-08-05 14:12:48 +0900
2014-08-05 14:12:49 +0900
2014-08-05 14:12:49 +0900

@sonots https://gist.github.com/shyouhei/90a5963340c535ce55cb こちらおためしいただけますか

1600 スレッドでは綺麗に 10 calls / sec になりました。が、
16000 スレッドにしてみたところ 19.354839 calls/sec のようなおかしな結果になりました。

処理の大半がメモリアクセスで止まっているように見えるとのこと。mutex が CPU キャッシュに乗りきらないとか。

やはりスレッド切りすぎは注意