#region Apache License // // Licensed to the Apache Software Foundation (ASF) under one or more // contributor license agreements. See the NOTICE file distributed with // this work for additional information regarding copyright ownership. // The ASF licenses this file to you under the Apache License, Version 2.0 // (the "License"); you may not use this file except in compliance with // the License. You may obtain a copy of the License at // // http://www.apache.org/licenses/LICENSE-2.0 // // Unless required by applicable law or agreed to in writing, software // distributed under the License is distributed on an "AS IS" BASIS, // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // See the License for the specific language governing permissions and // limitations under the License. // #endregion namespace NotLogging { using System; using System.Collections; using log4net; using log4net.Appender; using log4net.Layout; using log4net.Repository; using log4net.Repository.Hierarchy; public class NotLogging { #region Init Code private static int WARM_UP_CYCLES = 10000; static readonly ILog SHORT_LOG = LogManager.GetLogger("A0123456789"); static readonly ILog MEDIUM_LOG= LogManager.GetLogger("A0123456789.B0123456789"); static readonly ILog LONG_LOG = LogManager.GetLogger("A0123456789.B0123456789.C0123456789"); static readonly ILog INEXISTENT_SHORT_LOG = LogManager.GetLogger("I0123456789"); static readonly ILog INEXISTENT_MEDIUM_LOG= LogManager.GetLogger("I0123456789.B0123456789"); static readonly ILog INEXISTENT_LONG_LOG = LogManager.GetLogger("I0123456789.B0123456789.C0123456789"); static readonly ILog[] LOG_ARRAY = new ILog[] { SHORT_LOG, MEDIUM_LOG, LONG_LOG, INEXISTENT_SHORT_LOG, INEXISTENT_MEDIUM_LOG, INEXISTENT_LONG_LOG}; static readonly TimedTest[] TIMED_TESTS = new TimedTest[] { new SimpleMessage_Bare(), new SimpleMessage_Array(), new SimpleMessage_MethodGuard_Bare(), new SimpleMessage_LocalGuard_Bare(), new ComplexMessage_Bare(), new ComplexMessage_Array(), new ComplexMessage_MethodGuard_Bare(), new ComplexMessage_MethodGuard_Array(), new ComplexMessage_MemberGuard_Bare(), new ComplexMessage_LocalGuard_Bare()}; private static void Usage() { System.Console.WriteLine( "Usage: NotLogging " + Environment.NewLine + "\t true indicates shipped code" + Environment.NewLine + "\t false indicates code in development" + Environment.NewLine + "\t runLength is an int representing the run length of loops" + Environment.NewLine + "\t We suggest that runLength be at least 1000000 (1 million)."); Environment.Exit(1); } /// /// Program wide initialization method /// /// private static int ProgramInit(String[] args) { int runLength = 0; try { runLength = int.Parse(args[1]); } catch(Exception e) { System.Console.Error.WriteLine(e); Usage(); } ConsoleAppender appender = new ConsoleAppender(new SimpleLayout()); if("false" == args[0]) { // nothing to do } else if ("true" == args[0]) { System.Console.WriteLine("Flagging as shipped code."); ((Hierarchy)LogManager.GetRepository()).Threshold = log4net.Core.Level.Warn; } else { Usage(); } ((Logger)SHORT_LOG.Logger).Level = log4net.Core.Level.Info; ((Hierarchy)LogManager.GetRepository()).Root.Level = log4net.Core.Level.Info; ((Hierarchy)LogManager.GetRepository()).Root.AddAppender(appender); return runLength; } #endregion /// /// The main entry point for the application. /// [STAThread] static void Main(string[] argv) { if (System.Diagnostics.Debugger.IsAttached) { WARM_UP_CYCLES = 0; argv = new string[] { "false", "2" }; } if(argv.Length != 2) { Usage(); } int runLength = ProgramInit(argv); System.Console.WriteLine(); System.Console.Write("Warming Up..."); if (WARM_UP_CYCLES > 0) { foreach(ILog logger in LOG_ARRAY) { foreach(TimedTest timedTest in TIMED_TESTS) { timedTest.Run(logger, WARM_UP_CYCLES); } } } System.Console.WriteLine("Done"); System.Console.WriteLine(); // Calculate maximum description length int maxDescLen = 0; foreach(TimedTest timedTest in TIMED_TESTS) { maxDescLen = Math.Max(maxDescLen, timedTest.Description.Length); } string formatString = "{0,-"+(maxDescLen+1)+"} {1,9:G} ticks. Log: {2}"; double delta; ArrayList averageData = new ArrayList(); foreach(TimedTest timedTest in TIMED_TESTS) { double total = 0; foreach(ILog logger in LOG_ARRAY) { delta = timedTest.Run(logger, runLength); System.Console.WriteLine(string.Format(formatString, timedTest.Description, delta, ((Logger)logger.Logger).Name)); total += delta; } System.Console.WriteLine(); averageData.Add(new object[] { timedTest, total/((double)LOG_ARRAY.Length) }); } System.Console.WriteLine(); System.Console.WriteLine("Averages:"); System.Console.WriteLine(); foreach(object[] pair in averageData) { string avgFormatString = "{0,-"+(maxDescLen+1)+"} {1,9:G} ticks."; System.Console.WriteLine(string.Format(avgFormatString, ((TimedTest)pair[0]).Description, ((double)pair[1]))); } } } abstract class TimedTest { abstract public double Run(ILog log, long runLength); abstract public string Description {get;} } #region Tests calling Debug(string) class SimpleMessage_Bare : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { log.Debug("msg"); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "log.Debug(\"msg\");"; } } } class ComplexMessage_MethodGuard_Bare : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { if(log.IsDebugEnabled) { log.Debug("msg" + i + "msg"); } } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "if(log.IsDebugEnabled) log.Debug(\"msg\" + i + \"msg\");"; } } } class ComplexMessage_Bare : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { log.Debug("msg" + i + "msg"); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "log.Debug(\"msg\" + i + \"msg\");"; } } } #endregion #region Tests calling Debug(new object[] { ... }) class SimpleMessage_Array : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { log.Debug(new object[] { "msg" }); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "log.Debug(new object[] { \"msg\" });"; } } } class ComplexMessage_MethodGuard_Array : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { if(log.IsDebugEnabled) { log.Debug(new object[] { "msg" , i , "msg" }); } } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "if(log.IsDebugEnabled) log.Debug(new object[] { \"msg\" , i , \"msg\" });"; } } } class ComplexMessage_Array : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { log.Debug(new object[] { "msg" , i , "msg" }); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "log.Debug(new object[] { \"msg\" , i , \"msg\" });"; } } } #endregion #region Tests calling Debug(string) (using class members) class ComplexMessage_MemberGuard_Bare : TimedTest { override public double Run(ILog log, long runLength) { return (new Impl(log)).Run(runLength); } override public string Description { get { return "if(m_isEnabled) m_log.Debug(\"msg\" + i + \"msg\");"; } } class Impl { private readonly ILog m_log; private readonly bool m_isEnabled; public Impl(ILog log) { m_log = log; m_isEnabled = m_log.IsDebugEnabled; } public double Run(long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { if(m_isEnabled) { m_log.Debug("msg" + i + "msg"); } } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } } } class SimpleMessage_LocalGuard_Bare : TimedTest { override public double Run(ILog log, long runLength) { bool isEnabled = log.IsDebugEnabled; DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { if (isEnabled) log.Debug("msg"); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "if (isEnabled) log.Debug(\"msg\");"; } } } class SimpleMessage_MethodGuard_Bare : TimedTest { override public double Run(ILog log, long runLength) { DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { if (log.IsDebugEnabled) log.Debug("msg"); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "if (log.IsDebugEnabled) log.Debug(\"msg\");"; } } } class ComplexMessage_LocalGuard_Bare : TimedTest { override public double Run(ILog log, long runLength) { bool isEnabled = log.IsDebugEnabled; DateTime before = DateTime.Now; for(int i = 0; i < runLength; i++) { if(isEnabled) log.Debug("msg" + i + "msg"); } DateTime after = DateTime.Now; TimeSpan diff = after - before; return ((double)diff.Ticks)/((double)runLength); } override public string Description { get { return "if (isEnabled) log.Debug(\"msg\" + i + \"msg\");"; } } } #endregion }