Performance Considerations
Adding all those logging statements, besides being somewhat ugly
(useful, but ugly!), has a performance penalty. You should be
aware of what the tradeoffs are before you start putting tons of
logging into your classes.
The most important thing to know is that when you construct a log
message to pass into one of the Kernel logging functions, it
actually constructs your message, even if the message is never
logged.
In a nutshell, that means doing this is slow:
<span class='keyword'></span>Kernel<span class='keyword'></span>.<span class='keyword'></span>finer<span class='keyword'></span>(<span class='keyword'></span><span class='instance'>self</span><span class='keyword'></span>.<span class='keyword'></span>logname<span class='keyword'></span>, '<span class='keyword'></span>timerExpired<span class='keyword'></span>', '<span class='keyword'></span>broadcasting<span class='keyword'></span>: ' +<br> <span class='keyword'></span>name<span class='keyword'></span> + ' <span class='keyword'></span>belches<span class='keyword'></span> <span class='keyword'></span>loudly<span class='keyword'></span>, ' +<br> '<span class='keyword'></span>and<span class='keyword'></span> <span class='keyword'></span>looks<span class='keyword'></span> <span class='keyword'></span>very<span class='keyword'></span> <span class='keyword'></span>embarrassed<span class='keyword'></span>.')
|
The slow part is using all those plusses (+) to construct the log
message. First the system constructs the message, then it passes that
message to Kernel.finer(). (It's just as slow if you use Python's %
operator).
It's actually pretty fast: so fast that you won't usually notice a
difference if you only do it once. So this style of logging is OK if
you're doing something that's not executing very often. However, if
you're in a fast loop, or doing something that's executing very often
(more than once per second, say), then you really don't want to do
this.
The best thing to do is to try to pass single strings to the
logging methods. For example, this is pretty fast:
Kernel.finer(self.logname, 'timerExpired', 'broadcasting to agent')
|
There's no string construction going on here. Another option
is that if you already have to construct the string, to show
to the user, then you can re-use it in your log message:
<span class='keyword'></span>target<span class='keyword'></span>.<span class='keyword'></span>message<span class='keyword'></span>(<span class='string'>"<span class='keyword'></span>You<span class='keyword'></span> <span class='keyword'></span>suddenly<span class='keyword'></span> <span class='keyword'></span>belch<span class='keyword'></span>."</span>)<br><span class='keyword'></span>msg<span class='keyword'></span> = <span class='keyword'></span>name<span class='keyword'></span> + <span class='string'>" <span class='keyword'></span>belches<span class='keyword'></span> <span class='keyword'></span>loudly<span class='keyword'></span>, <span class='keyword'></span>and<span class='keyword'></span> <span class='keyword'></span>looks<span class='keyword'></span> <span class='keyword'></span>very<span class='keyword'></span> <span class='keyword'></span>embarrassed<span class='keyword'></span> <span class='keyword'></span>about<span class='keyword'></span> <span class='keyword'></span>it<span class='keyword'></span>."</span><br><span class='keyword'></span>Kernel<span class='keyword'></span>.<span class='keyword'></span>finest<span class='keyword'></span>(<span class='keyword'></span><span class='instance'>self</span><span class='keyword'></span>.<span class='keyword'></span>logname<span class='keyword'></span>, '<span class='keyword'></span>timerExpired<span class='keyword'></span>', <span class='keyword'></span>msg<span class='keyword'></span>)<br><span class='keyword'></span>target<span class='keyword'></span>.<span class='keyword'></span>broadcast<span class='keyword'></span>(<span class='keyword'></span>msg<span class='keyword'></span>)
|
Another trick you can use is to squeeze more information into the
method name. There's no rule that says the method name you pass in
actually has to be the name of the method you're executing! It's just
for your own use, so you could just do something like this:
<span class='keyword'></span>Kernel<span class='keyword'></span>.<span class='keyword'></span>finer<span class='keyword'></span>(<span class='keyword'></span><span class='instance'>self</span><span class='keyword'></span>.<span class='keyword'></span>logname<span class='keyword'></span>, '<span class='keyword'></span>timerExpired<span class='keyword'></span>: <span class='keyword'></span>rolled<span class='keyword'></span>:', <span class='keyword'></span>str<span class='keyword'></span>(<span class='keyword'></span>roll<span class='keyword'></span>))<br><span class='keyword'></span>Kernel<span class='keyword'></span>.<span class='keyword'></span>finer<span class='keyword'></span>(<span class='keyword'></span><span class='instance'>self</span><span class='keyword'></span>.<span class='keyword'></span>logname<span class='keyword'></span>, '<span class='keyword'></span>timerExpired<span class='keyword'></span>: <span class='keyword'></span>pronoun<span class='keyword'></span> = ', <span class='keyword'></span>pronoun<span class='keyword'></span>)<br><span class='keyword'></span>Kernel<span class='keyword'></span>.<span class='keyword'></span>finer<span class='keyword'></span>(<span class='keyword'></span><span class='instance'>self</span><span class='keyword'></span>.<span class='keyword'></span>logname<span class='keyword'></span>, '<span class='keyword'></span>timerExpired<span class='keyword'></span>: <span class='keyword'></span>name<span class='keyword'></span> = ', <span class='keyword'></span>name<span class='keyword'></span>)
|
In all three lines above, we're not doing string construction, so the
calls are quite a bit faster. The str(roll) is a wee bit expensive,
but nothing to really worry about.
And of course, your best option (performance-wise) is to just
comment out the calls, or remove them completely:
<span class='keyword'></span>target<span class='keyword'></span>.<span class='keyword'></span>message<span class='keyword'></span>(<span class='string'>"<span class='keyword'></span>You<span class='keyword'></span> <span class='keyword'></span>suddenly<span class='keyword'></span> <span class='keyword'></span>belch<span class='keyword'></span>."</span>)<br><span class='keyword'></span>msg<span class='keyword'></span> = <span class='keyword'></span>name<span class='keyword'></span> + <span class='string'>" <span class='keyword'></span>belches<span class='keyword'></span> <span class='keyword'></span>loudly<span class='keyword'></span>, <span class='keyword'></span>and<span class='keyword'></span> <span class='keyword'></span>looks<span class='keyword'></span> <span class='keyword'></span>very<span class='keyword'></span> <span class='keyword'></span>embarrassed<span class='keyword'></span> <span class='keyword'></span>about<span class='keyword'></span> <span class='keyword'></span>it<span class='keyword'></span>."</span><br><span class='comment'>#Kernel.finest(self.logname, 'timerExpired', msg)</span><br><span class='keyword'></span>target<span class='keyword'></span>.<span class='keyword'></span>broadcast<span class='keyword'></span>(<span class='keyword'></span>msg<span class='keyword'></span>)
|
Then there's zero performance overhead. The downside is that when you
want to go debug the code, you have to go in and uncomment all the
logging lines. It's a tradeoff between performance and convenience.
We recommend that you don't worry too much about it unless you notice
(or someone tells you) that your classes are slow.
If you decide to go through the Advanced Logging lessons, then you'll
learn one more performance trick that's sort of the best of all
worlds, but it's not possible using the built-in wyvern.lib.Kernel
logging functions. You have to go straight to the Logging system
itself, and in most cases, you really don't need to do that.
In the next lesson, we cover Exception handling, which can be useful
for seeing how the heck you got to a particular place in your
code.
|