jamwt/diesel — pull request #66 by dowski (2013-04-18 16:58:39+00:00)
Title: Better Hub Timer Handling Performance

We ran up against an issue in production where a service that was handling many mostly-idle but some quite-active clients was getting close to maxing out the CPU.

I did some profiling and found this:

```
Thu Apr 18 08:39:38 2013 zmq_node.pstats

433038244 function calls (430385458 primitive calls) in 941.237 CPU seconds

Ordered by: internal time
List reduced from 1087 to 25 due to restriction <25>

ncalls tottime percall cumtime percall filename:lineno(function)
164098 503.328 0.003 503.328 0.003 {method 'poll' of 'select.epoll' objects}
193728608 135.454 0.000 179.959 0.000 hub.py:66(__cmp__)
86906 56.633 0.001 155.571 0.002 {sorted}
86926 48.838 0.001 129.860 0.001 {method 'remove' of 'collections.deque' objects}
193728644 44.505 0.000 44.505 0.000 {cmp}
```

I sorted the profile stats by cumulative time and found this:

```
96168 0.295 0.000 130.310 0.001 hub.py:40(cancel)
```

Looking at the code, it was pretty clear when canceling a timer, we were doing an O(N) `.remove()` call on our `timers` deque. Additionally, as the profiling output showed, that and the sorting of the `timers` deque was triggering *hundreds of millions* of calls to a Python-level `__cmp__` method (belonging to `Timer`).

We now store `Timer`s in a dictionary and removal is O(1). We also don't sort `Timer` instances now.

Here are some results of a benchmark I wrote (included in this PR) against the old and new timer cancellation code. The the benchmark runs N producer/consumer loops and should finish in close to 10s if everything is running smoothly. It outputs total time and a sample of CPU times while the benchmark is running.

```
# old code
$ python examples/timer_bench.py 25
done in 10.02 secs
[27, 14, 9, 7, 6, 5, 4, 4, 3, 3]
$ python examples/timer_bench.py 250
done in 10.05 secs
[34, 23, 18, 16, 14, 13, 12, 12, 12, 11]
$ python examples/timer_bench.py 2500
done in 39.71 secs
[83, 92, 99, 99, 99, 99, 99, 99, 99, 99]
```

Notice how with 2500 producer/consumer pairs the old code swamps the CPU and isn't able to keep up and hit the timings.

```
# new code
$ python examples/timer_bench.py 25
done in 10.03 secs
[28, 14, 9, 7, 6, 5, 4, 4, 3, 3]
$ python examples/timer_bench.py 250
done in 10.04 secs
[34, 20, 15, 12, 11, 10, 9, 8, 8, 7]
$ python examples/timer_bench.py 2500
done in 10.22 secs
[84, 52, 54, 53, 53, 53, 52, 53, 53, 52]
```

Even with 2500 producers/consumers, it stays around 50% CPU and finishes very close to the tests with a smaller N.

The big internal change is that `Timer`s are compared by `id()` now, not by `trigger_time`. I think this is OK because the `timers` deque now contains tuples of `(trigger_time, id(timer))` and still sorts correctly.

The `timers` deque is also cleared lazily now - if a `Timer` is canceled, it is only removed from the `timer_map` so we don't have to scan `timers` on each removal.