c# - Using log4net Context Properties has negative impact on performance? -
posting see if has had similar experience , if there's known workarounds?
update: log4net team has acknowledged issue , see link: https://issues.apache.org/jira/browse/log4net-429
i've found if use pattern uses custom property, logging 3-5 times slower. illustrate have setup example project logs 10000 times 2 different loggers , appenders. 1 of them has custom string property.
typical output:
elapsed time (no property): 800ms, elapsed time (with property) 2400ms
three times slower when logging context property
after doing decompiling think output parameter end touching current user name in process, expensive operation. i'm not sure, think that's whats going on.
to reproduce it, create console application , use following app.config , main.cs
app.config:
<?xml version="1.0" encoding="utf-8" ?> <configuration> <configsections> <section name="log4net" type="log4net.config.log4netconfigurationsectionhandler, log4net" /> </configsections> <log4net> <appender name="nopropertyappender" type="log4net.appender.consoleappender"> <layout type="log4net.layout.patternlayout"> <conversionpattern value="%message%newline" /> </layout> </appender> <appender name="propertyappender" type="log4net.appender.consoleappender"> <layout type="log4net.layout.patternlayout"> <conversionpattern value="%property{customproperty}- %message%newline" /> </layout> </appender> <logger name="noproperty"> <level value="debug" /> <appender-ref ref="nopropertyappender" /> </logger> <logger name="hasproperty"> <level value="debug" /> <appender-ref ref="propertyappender" /> </logger> </log4net> <startup> <supportedruntime version="v4.0" sku=".netframework,version=v4.5" /> </startup> </configuration>
main.cs
namespace consoleapplication11 { class program { //private static readonly ilog log = logmanager.getlogger(typeof(program)); static void main(string[] args) { // arrange log4net.config.xmlconfigurator.configure(); globalcontext.properties["customproperty"] = "test"; var nrofrepetitions = 10000; var nopropertylogger = logmanager.getlogger("noproperty"); var propertylogger = logmanager.getlogger("hasproperty"); var nopropertystopwatch = new stopwatch(); var propertystopwatch = new stopwatch(); nopropertystopwatch.start(); (int = 0; < 10000; i++) { nopropertylogger.info("logging without custom parameter."); } nopropertystopwatch.stop(); propertystopwatch.start(); (int = 0; < nrofrepetitions; i++) { propertylogger.info("logging custom parameter"); } propertystopwatch.stop(); nopropertylogger.info(string.format("elapsed time: (no property) {0}", nopropertystopwatch.elapsedmilliseconds)); propertylogger.info(string.format("elapsed time: (with property) {0}", propertystopwatch.elapsedmilliseconds)); console.readline(); } } }
Comments
Post a Comment