ipdevpoll logging system uses too many resources

[Morten Brekkevold]

The ipdevpoll framework uses the ContextLogger in several classes to have simple access to logging with context information. The ContextLogger class is a Python descriptor that can search the current execution stack for context information, creating and caching a LoggerAdapter with this context when found.

The ContextLogger uses inspect.stack() to get the stack at the current point of execution, but this function does a lot more than just retrieve the current stack frames, it also retrieves meta-information and source code context from each frame. This stack inspection occurs very often in ipdevpoll, as most data container objects have lots of debug logging going on, and each collection job can create a huge amount of these containers.

Profiling of ipdevpoll reveals that as much as 30% of ipdevpoll's execution time is spent inspecting the call stack because of logging; this is ridiculous - logging should not have this kind of impact on a system, especially when there isn't any debug level logging going on.

This is a must fix! ContextLoggers were introduced in ipdevpoll in NAV 3.11.0, the latest version with this implementation being 3.11.5.

[Morten Brekkevold (mbrekkevold)]

fix here: http://nav.uninett.no/hg/stable/rev/5e5e4245e90c