investigate event dispatch optimization and expose a switch for enable/disable the log system

[exarkun]

A Twisted UDP echo server on an 2.2GHz Opteron can saturate a 100mbit/sec network, but doing so requires about 80% CPU. Since in this application there is essentially no application overhead, this is all time spent in Twisted somewhere. A similar application in C can do the same task using about 10% CPU.

There are probably some things we can do to cut down on this event dispatch overhead. One particularly obvious area (but not necessarily the only or even the most costly) is the involvement of the logging system in event dispatch. Removing the callWithLogger usage from select reactor yields approximately 15% reduction in CPU usage for the same task. There is probably a way to preserve this functionality without the current overhead, such as by pre-constructing context dictionaries, calling logPrefix only once per selectable, avoiding the extra method call of callWithLogger and going straight to callWithContext, avoiding the context copy since the reactor is guaranteed to be at the top of the context stack, etc.

[glyph]

As other recent discussion has revealed, the functionality as currently specified is somewhat ad-hoc and inconsistent. Making it more regular might make it a lot easier to optimize, so feel free to go down that route; it's just about impossible to write application code that actually relies on the behaviors of the logging system (as they're not only unpredictable, but also mostly undocumented and untested).

[therve]

I've started to look at this. The current implementation is really really weird and hard to read. From what I understand, this complex system is used for only one thing: keep the logPrefix available in the chain of deferred (and calls in threads), in the system key. The other key, isError, is just to give a default and could trivially be removed.

First, I think logPrefix should be a attribute instead of a method. Nothing use the fact it's a method currently. Of course the pain is backward compatibility (but isn't it always the case ?:).

Then, if we agree on my first point, we could find an easier way to do the same thing.

[exarkun]

Deferreds aren't actually supported, nor threads as far as I recall. twisted.python.context only works for boring, synchronous call stacks. It's a way of passing the logPrefix from a place where it is known, inside the reactor, to a place where it is needed, inside the logging code, without having to pass it through all of the intermediate stack frames, which probably include application code which can't be trusted, relied on, or required to pass the information through.

[pniccoli]

I had the same high cpu usage in my program written in twisted, and after profiling it I've noticed that a lot of time was spent in the logging system. I wrote a simple echo client in twisted, and the performances after disabling the logging system increased of around the 15% (as said above). I know that this is not the correct way to modify it, but if you have tested your application and you are sure it's working, maybe you can use this simple trick to obtain some extra performances. I added a patch file, in your program you just have to add those two lines:

from twisted.python import log
log.logSwitch = False

[exarkun]

Thanks for your input pniccoli. It's great to get real-world numbers like this.

(As a matter of workflow, I'm removing the review keyword, since you're not really proposing your attached patch for inclusion in Twisted.)