further optimize conf.settings access when logging is enabled #5739
Conversation
|
a modest playbook, before (with logging enabled): notice how only about 10% of the total time is spent idle polling for new messages (the blue right-hand side of the graph)
|
|
The same playbook, after this PR. Notice how this version spends almost all of its time where you expect:
this graph is what I'd expect to see in a system that is keeping up with spikes of stdout
|
| @@ -186,8 +194,6 @@ def set_many(self, data, **kwargs): | |||
| self.set(key, value, log=False, **kwargs) | |||
|
|
|||
| def _handle_encryption(self, method, key, value): | |||
| TransientSetting = namedtuple('TransientSetting', ['pk', 'value']) | |||
There was a problem hiding this comment.
It turns out namedtuples are really slow to create on demand like this. In my testing, this one line was accounting for almost 25% of the total time spent on event processing when logging was enabled:
looks like other communities have noticed this about Python as well:
https://rhye.org/post/python-cassandra-namedtuple-performance/
https://bugs.python.org/issue28638
|
Build succeeded.
|
| self.cluster_host_id = settings.CLUSTER_HOST_ID | ||
| self.tower_uuid = None | ||
| uuid = ( | ||
| getattr(settings, 'LOG_AGGREGATOR_TOWER_UUID', None) or |
There was a problem hiding this comment.
It's a lot less expensive to just set these once instead of doing a lookup on every log emit; they're generated once at install time anyways.
| @@ -316,6 +317,7 @@ def serialize(cls, message): | |||
| def get_handler_class(self, protocol): | |||
| return HANDLER_MAPPING.get(protocol, AWXNullHandler) | |||
|
|
|||
| @cachetools.cached(cache=cachetools.TTLCache(maxsize=128, ttl=3)) | |||
| def get_handler(self, custom_settings=None, force_create=False): | |||
There was a problem hiding this comment.
We're calling this constantly, and it is absolutely destroying us when logging is enabled; this is a compromise to cache this slightly and give memcached a break when event logging is enabled.
awx/main/utils/handlers.py
Outdated
| @@ -342,10 +344,14 @@ def get_handler(self, custom_settings=None, force_create=False): | |||
| self._handler.setFormatter(self.formatter) | |||
| return self._handler | |||
|
|
|||
| @cachetools.cached(cache=cachetools.TTLCache(maxsize=1, ttl=3)) | |||
There was a problem hiding this comment.
Another one that we're calling all over the place.
ryanpetrello
force-pushed
the
optimize-callback-with-logging
branch
from
abb65cb
to
c8d47b5
Compare
|
Build failed.
|
ryanpetrello
force-pushed
the
optimize-callback-with-logging
branch
from
c8d47b5
to
aeb7a63
Compare
the callback receiver is still fairly slow when logging is enabled due to constant setting lookups; this speeds things up considerably related: ansible#5618
ryanpetrello
force-pushed
the
optimize-callback-with-logging
branch
from
aeb7a63
to
e18639b
Compare
|
Build succeeded.
|
|
Build succeeded (gate pipeline).
|
the callback receiver is still fairly slow when logging is enabled due
to constant setting lookups; this speeds things up considerably
related: #5618