tmm1/rblineprof — pull request #19 by spraints (2013-06-20 19:05:07+00:00)
Title: 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
```