From: takeru sasaki <sasaki.takeru@...>
Date: 2008-06-02T14:44:24+09:00
Subject: [ruby-list:44994] Re: 重いタスクと平行にirbを使うと遅い？

佐々木です。

たびたびすみません。

どうやらirbではなく、readlineに原因がありそうというところまでわかりました。
irbをreadlineを使わないようにしたら問題が起こらなくなりました。

readlineが入力待ち状態の時にスレッドの切替が少ないのかなあと思います。
readlineにenterを押して入力するタイミングでは切替が発生してタスクが進んでいます。


readlineとgetsを比較する再現コードです。
---------------------------
require "benchmark"

def _t(s)
  $stderr.puts(s)
end
$stdout.sync = true

class Task
  attr_reader :count
  JOBS = 10000000
  def initialize(name)
    @name  = name
  end
  def run
    @start = Time.now
    puts "\n#{@name}:%s" % Benchmark.measure{
      @count = 0
      JOBS.times{
        @count += 1
        if @count%(JOBS/10)==0
          puts status
        end
      }
    }
    puts "task finished. @name=#{@name}"
  end
  def status
    elapse = Time.now-@start
    "name=#{@name} #{(100*@count/JOBS).to_i}%
speed=#{'%f'%(@count/elapse)} count=#{@count} elapse=#{elapse}"
  end
end

thread3 = Thread.start{
  $taskC = Task.new("C")
  $taskC.run
}
if ARGV[0]=="readline"
  require "readline"
  while buf = Readline.readline("> ", true)
    print "-> ", buf, "\n"
    puts $taskC.status
  end
elsif ARGV[0]=="gets"
  while true
    s = $stdin.gets
    puts "gets -> #{s}"
    puts $taskC.status
  end
else
  raise "ruby irb_slow.rb readline|gets"
end
---------------------------


% ~/ruby187/bin/ruby -v irb_slow.rb readline
ruby 1.8.7 (2008-05-31 patchlevel 0) [i686-darwin8.11.1]
>
->
name=C 0% speed=2643.992819 count=52040 elapse=19.682353 ★19秒後0%
>
->
name=C 1% speed=3822.670383 count=136027 elapse=35.584287 ★35秒たっても1%
> ^C^Cirb_slow.rb:40: Interrupt

% ~/ruby187/bin/ruby -v irb_slow.rb gets
ruby 1.8.7 (2008-05-31 patchlevel 0) [i686-darwin8.11.1]
name=C 10% speed=1002050.194698 count=1000000 elapse=0.997954
name=C 20% speed=999638.630635 count=2000000 elapse=2.000723
name=C 30% speed=1000346.453322 count=3000000 elapse=2.998961
name=C 40% speed=999731.322207 count=4000000 elapse=4.001075
name=C 50% speed=1000256.465758 count=5000000 elapse=4.998718
name=C 60% speed=999587.170499 count=6000000 elapse=6.002478
name=C 70% speed=999584.886676 count=7000000 elapse=7.002907
name=C 80% speed=999357.288344 count=8000000 elapse=8.005145
name=C 90% speed=999628.138333 count=9000000 elapse=9.003348
name=C 100% speed=999338.837425 count=10000000 elapse=10.006616

C:  9.910000   0.040000   9.950000 ( 10.006724)
task finished. @name=C

gets ->
name=C 100% speed=796855.353780 count=10000000 elapse=12.549329
gets ->
name=C 100% speed=718121.663741 count=10000000 elapse=13.925217 ★13秒で100%
^Cirb_slow.rb:46:in `gets': Interrupt
        from irb_slow.rb:46