天泣記

#1 copy-on-write fork による親プロセスの速度低下

copy-on-write な fork では、 fork した時点で、親プロセスと子プロセスがメモリを read only で共有し、 write 時には page fault が起きてページをコピーして write 可能にした後、write を続行する。

ここで、子プロセスが exec した後は、そのメモリを使っているのは親プロセスだけになるのでコピーは不要になるが、 write しようとしたときに page fault が起きることは変わらない。

このあたりの動作は以下の NetBSD のドキュメントに動作が記述されている。 (もしかしたら、OSによっては微妙に動作が違うこともあるかもしれないけれど)

NetBSD ドキュメンテーション: なぜ伝統的な vfork()を実装したのか

この、親プロセスでメモリが read only になったままで、書き込みのたびに page fault が起きるという動作は (コピーは起きないにせよ) かなり遅くなることもあるのではないか、という疑問を感じた。

というわけで (Linux で) 試してみた。

% uname -mrsv
Linux 4.19.0-2-amd64 #1 SMP Debian 4.19.16-1 (2019-01-17) x86_64

まず、Transparent huge page (THP) を disable する。 (Ruby 2.6 では内部で THP を disable している ([Feature #14705], r63253) のだが、Ruby 2.5 以前ではしてないので、これは 4K page という動作で揃えている)

# echo never > /sys/kernel/mm/transparent_hugepage/enabled

この状態で、大きなメモリに (各ページ毎に 1byte の) 書き込みを行う時間を測定した。 10回測定し、fork してからまた 10回測定する。

以下の結果をみると、明らかに fork 直後の回が 10倍くらい遅くなっている。

% ruby-2.6.2 -e '
pagesize = 4096
n = 100000
s = "x" * (n*pagesize)
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}
puts
Process.wait fork {}
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}'
0.00733914 *******
0.00699243 ******
0.00674534 ******
0.00777585 *******
0.00836382 ********
0.00729977 *******
0.00705439 *******
0.00687936 ******
0.00667030 ******
0.00662619 ******

0.06490101 ****************************************************************
0.00664682 ******
0.00662405 ******
0.00670339 ******
0.00657027 ******
0.00700166 *******
0.00666423 ******
0.00650362 ******
0.00669207 ******
0.00651883 ******

次に、fork のかわりに、system("true") を使うと、以下のように、fork と違って遅くならない。これは、vfork を使っているからだろう。

% ruby-2.6.2 -e '
pagesize = 4096
n = 100000
s = "x" * (n*pagesize)
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}
puts
system("true")
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}'
0.00758229 *******
0.00701581 *******
0.00680411 ******
0.00673921 ******
0.00668358 ******
0.00671528 ******
0.00657470 ******
0.00660746 ******
0.00661486 ******
0.00670212 ******

0.00674013 ******
0.00700635 *******
0.00678113 ******
0.00657952 ******
0.00659784 ******
0.00678082 ******
0.00658584 ******
0.00661802 ******
0.00653398 ******
0.00654583 ******

vfork を使うようになったのは ruby 2.2 からなので、 ruby 2.1.10 で試すと、これは system でも遅くなる。

% ruby-2.1.10 -e '
pagesize = 4096
n = 100000
s = "x" * (n*pagesize)
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}
puts
system("true")
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}'
0.00678418 ******
0.00661911 ******
0.00631097 ******
0.00615733 ******
0.00612787 ******
0.00625961 ******
0.00616606 ******
0.00614166 ******
0.00615436 ******
0.00616540 ******

0.06327575 ***************************************************************
0.00622857 ******
0.00624134 ******
0.00617376 ******
0.00617710 ******
0.00638290 ******
0.00618077 ******
0.00615743 ******
0.00615407 ******
0.00613252 ******

ここで、Transparent huge page (THP) を enable する。

# echo always > /sys/kernel/mm/transparent_hugepage/enabled

すると、そんなに遅くならないようになる。 THP って効く (ことがある) のだな。

% ruby-2.1.10 -e '
pagesize = 4096
n = 100000
s = "x" * (n*pagesize)
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}
puts
system("true")
10.times {
  t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  n.times {|i| s.setbyte(i*pagesize,0) }
  t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
  t = t2-t1
  printf "%.8f %s\n", t, "*"*(t*1000).to_i
}'
0.00914092 *********
0.00847733 ********
0.00838931 ********
0.00775660 *******
0.00810754 ********
0.00699371 ******
0.00679120 ******
0.00660573 ******
0.00733054 *******
0.00661029 ******

0.00728163 *******
0.00663571 ******
0.00679257 ******
0.00704892 *******
0.00651190 ******
0.00643143 ******
0.00643470 ******
0.00717451 *******
0.00673541 ******
0.00647267 ******

天泣記

2019-03-26 (Tue)

2019-03-27 (Wed)