Threads

# Before

Note the difference between the simple timer and rblineprof on lines 30, 34, 37, 53.

```
$ ruby -I. -Iext threadtest.rb
...
                                    | 26 | def getprofile
                                    | 27 |   lineprof(File.expand_path(__FILE__)) do
24.073ms vs 24.084ms (10.712ms cpu) | 28 |     log(__LINE__) do
             0.037ms ( 0.012ms cpu) | 29 |       t = Thread.new do
23.902ms vs 18.350ms ( 6.386ms cpu) | 30 |         log(__LINE__) do
            18.327ms ( 6.372ms cpu) | 31 |           thread_work
                                    | 32 |         end
                                    | 33 |       end
18.380ms vs 24.004ms (10.671ms cpu) | 34 |       log(__LINE__) do
            23.957ms (10.659ms cpu) | 35 |         main_work
                                    | 36 |       end
 5.615ms vs  0.020ms ( 0.009ms cpu) | 37 |       log(__LINE__) do
                                    | 38 |         t.join
                                    | 39 |       end
                                    | 40 |     end
                                    | 41 |   end
                                    | 42 | end
                                    | 43 |
                                    | 44 | def thread_work
            18.325ms ( 6.371ms cpu) | 45 |   work(2000)
                                    | 46 | end
                                    | 47 |
                                    | 48 | def main_work
            23.941ms (10.649ms cpu) | 49 |   work(3000)
                                    | 50 | end
                                    | 51 |
                                    | 52 | def work(n)
28.532ms vs 34.103ms (10.721ms cpu) | 53 |   log(__LINE__) { sleep 0.01          }
13.634ms vs 13.667ms (10.501ms cpu) | 54 |   log(__LINE__) { n.times { 2**1024 } }
                                    | 55 | end
                                    | 56 |
                                    | 57 | def log(line)
             0.045ms ( 0.032ms cpu) | 58 |   start = Time.now
                                    | 59 |   yield
                                    | 60 | ensure
             0.192ms ( 0.109ms cpu) | 61 |   $line_times[line] += Time.now - start
                                    | 62 | end
                                    | 63 |
                                    | 64 | main
```

# After

The wall clock time is easy to verify with the manual timer. I think it's right.

I don't think the CPU time is right: I would expect line 37 to match line 38, and I would expect line 53 to be 0.

I haven't checked to see if allocations are correct.

```
$ ruby -I. -Iext threadtest.rb
...
                                    | 26 | def getprofile
                                    | 27 |   lineprof(File.expand_path(__FILE__)) do
25.985ms vs 26.010ms (11.988ms cpu) | 28 |     log(__LINE__) do
             0.029ms ( 0.010ms cpu) | 29 |       t = Thread.new do
24.719ms vs 25.835ms (11.904ms cpu) | 30 |         log(__LINE__) do
            24.711ms (11.504ms cpu) | 31 |           thread_work
                                    | 32 |         end
                                    | 33 |       end
19.789ms vs 19.804ms ( 7.225ms cpu) | 34 |       log(__LINE__) do
            19.783ms ( 7.213ms cpu) | 35 |         main_work
                                    | 36 |       end
 6.121ms vs  6.142ms ( 4.731ms cpu) | 37 |       log(__LINE__) do
             6.110ms ( 0.009ms cpu) | 38 |         t.join
                                    | 39 |       end
                                    | 40 |     end
                                    | 41 |   end
                                    | 42 | end
                                    | 43 |
                                    | 44 | def thread_work
            24.710ms (11.503ms cpu) | 45 |   work(2000)
                                    | 46 | end
                                    | 47 |
                                    | 48 | def main_work
            19.782ms ( 7.212ms cpu) | 49 |   work(3000)
                                    | 50 | end
                                    | 51 |
                                    | 52 | def work(n)
29.751ms vs 29.836ms ( 7.329ms cpu) | 53 |   log(__LINE__) { sleep 0.01          }
14.612ms vs 14.650ms (11.384ms cpu) | 54 |   log(__LINE__) { n.times { 2**1024 } }
                                    | 55 | end
                                    | 56 |
                                    | 57 | def log(line)
             0.049ms ( 0.029ms cpu) | 58 |   start = Time.now
                                    | 59 |   yield
                                    | 60 | ensure
             0.175ms ( 0.113ms cpu) | 61 |   $line_times[line] += Time.now - start
                                    | 62 | end
                                    | 63 |
                                    | 64 | main
```