Logging config dramatically impacts throughput

[Marvin Addison]

I wanted to report a surprising finding from load testing the past couple
days. I was testing against our dev environment where we log
net.shibboleth.idp at DEBUG, which as you know generates a mountain of
output. I happened to turn it down to INFO and noticed a 2-8x increase in
throughput. The effect was not surprising, of course, but the magnitude was
shocking.

I did some further testing and it appears that this is not (solely) an IO
throughput issue. With the IDP_PROCESS logger at INFO, I toggled the
IDP_PROTOCOL logger on/off and noted only a moderate (20-30%) effect on
throughput. That suggests that there's something about writing large
numbers of logging _events_ that dramatically impacts throughput. I was
able to mitigate that effect by wrapping the IDP_PROCESS logger in an async
appender, which provided throughput at DEBUG levels similar to the default
config at INFO.

    <appender name="SYNC_IDP_PROCESS"
class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>/apps/logs/splunk/idp-process.log</File>
        ...
    </appender>
    <appender name="IDP_PROCESS"
class="ch.qos.logback.classic.AsyncAppender">
        <queueSize>500</queueSize>
        <discardingThreshold>0</discardingThreshold>
        <appender-ref ref="SYNC_IDP_PROCESS" />
    </appender>

I'm sure no one will run the IdP with noisy categories at DEBUG for any
extended period of time, so it's probably not relevant in general. That
said, it costs virtually nothing to wrap IDP_PROCESS in an async wrapper to
prevent potentially serious degradations in performance when DEBUG logging
is enabled for troubleshooting.

M
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/dev/attachments/20150928/0e0cec3d/attachment-0001.html>