- Most real-world systems have to deal with multiple clients simultaneously. In a - typical multithreaded implementation of such a system, different threads will - handle different clients. Logging is especially well suited to trace and debug - complex distributed applications. An approach to differentiate the - logging output of one client from another is to instantiate a new separate - logger for each client. However this promotes the proliferation of loggers and - increases the management overhead of logging. -
-- A lighter technique is to uniquely stamp each log request initiated from the - same client interaction. -
-- Log4net supports different types of contextual logging and contexts with different scopes. -
- -- Contextual data can be set in different scopes. These contexts have progressively narrower visibility. - In the logging event itself the values from all of the contexts are combined together such that - values specified in a lower scoped context hide values from a higher context. -
- -| Scope | -Type | -Description | -
|---|---|---|
| Global | -log4net.GlobalContext | -- The global context is shared by all threads in the current AppDomain. - This context is thread safe for use by multiple threads concurrently. - | -
| Thread | -log4net.ThreadContext | -- The thread context is visible only to the current managed thread. - | -
| Logical Thread | -log4net.ThreadLogicalContext | -- The logical thread context is visible to a logical thread. Logical - threads can jump from one managed thread to another. For more details - see the .NET API System.Runtime.Remoting.Messaging.CallContext. - | -
| Event | -log4net.Core.LoggingEvent | -- Each event captures the current contextual state at the time the event - is generated. Contextual data can be set on the event itself. This context - is only visible to the code generating the event itself. - | -
- The log4net contexts store properties, i.e. name value pairs. The name is a string - the value is any object. A property can be set as follows: -
--log4net.GlobalContext.Properties["name"] = value; -
- If properties with the same name are set in more than one context scope then - the value in the narrowest scope (lower down in the list above) will hide the - other values. -
-- The property values are stored as objects within the LoggingEvent. - The PatternLayout supports rendering the value of a named - property using the %property{name} syntax. The value is - converted to a string by passing it to the log4net.ObjectRenderer.RendererMap - which will locate any custom renderer for the value type. The default behavior for - custom types is to call the object's ToString() method. -
- -- An active property value is one who's value changes over time. -
-- For example, imagine a custom type that implemented the - ToString() method to return the - number of bytes allocated by the runtime garbage collector. -
-
-public class GCAllocatedBytesHelper
-{
- public override string ToString()
- {
- return GC.GetTotalMemory(true).ToString();
- }
-}- An instance of this type can be added to the log4net.GlobalContext - during application startup: -
--log4net.GlobalContext.Properties["GCAllocatedBytes"] = new GCAllocatedBytesHelper(); -
- Once this property is set in the context all subsequent logging events will have a property - called GCAllocatedBytes. The value of the property will be an instance of the - GCAllocatedBytesHelper type. When this value is rendered to a - string by calling the ToString method the current number of bytes - allocated by the garbage collector will be returned and included in the output. -
- -- Sometimes simple key value pairs are not the most convenient way of capturing contextual - information. A stack of information is a very convenient way of storing data especially - as our applications tend to be stack based. -
-- The ThreadContext and LogicalThreadContext - also support storing contextual data in a stack. The stack is stored in context property, - therefore stacks have names and more than one stack can exist in the same context. A property - value set in a narrower context would override a stack with the same property name set in a - wider scoped context. -
-- The stack supports Push and Pop methods. - As more contextual data is pushed onto the stack the stack grows. When the stack is rendered - all the data pushed onto the stack is output with the most recent data to the right hand - end of the string. -
-- As the stack is just an object stored in the context properties it is also rendered - using the same PatternLayout syntax: %property{name}. - Where name is the name of the stack. -
-- Calls the the stack's Push and Pop - methods must be matched up so that each push has a corresponding pop. The - Push method also returns an IDisposable - object that will perform the required pop operation when it is disposed. This allows - the C# using syntax to be used to automate the stack management. -
-
-using(log4net.ThreadContext.Stacks["NDC"].Push("context"))
-{
- log.Info("Message");
-}
-- The INFO level log has a stack stored in its NDC property. The top item in the - stack is the string context. - The using syntax ensures that the value context is popped off the stack - at the end of the block. -
-- The using - syntax is recommended because it removes some work load from the developer and - reduces errors in matching up the Push and Pop calls, especially when exceptions - can occur. -
-- The NDC (Nested Diagnostic Context) exists for compatibility - with older versions of log4net. This helper class implements a stack which is stored - in the thread context property named NDC. -
-- The MDC (MappedDiagnostic Context) exists for compatibility - with older versions of log4net. This helper class implements a properties map which is - mapped directly through to the thread context properties. -
-- To illustrate this point, let us take the example of a web service delivering - content to numerous clients. The web service can build the NDC at the very - beginning of the request before executing other code. The contextual - information can be the client's host name and other information inherent to the - request, typically information contained in cookies. Hence, even if the web - service is serving multiple clients simultaneously, the logs initiated by the - same code, i.e. belonging to the same logger, can still be distinguished - because each client request will have a different NDC stack. Contrast this with - the complexity of passing a freshly instantiated logger to all code exercised - during the client's request. -
-- Nevertheless, some sophisticated applications, such as virtual hosting web - servers, must log differently depending on the virtual host context and also - depending on the software component issuing the request. Log4net supports - multiple logger repositories. This would allow each virtual host to possess its own copy - of the logger hierarchy. Configuring multiple logger hierarchies is beyond the - scope of this document. -
- -+ Most real-world systems have to deal with multiple clients simultaneously. In a + typical multithreaded implementation of such a system, different threads will + handle different clients. Logging is especially well suited to trace and debug + complex distributed applications. An approach to differentiate the + logging output of one client from another is to instantiate a new separate + logger for each client. However this promotes the proliferation of loggers and + increases the management overhead of logging. +
++ A lighter technique is to uniquely stamp each log request initiated from the + same client interaction. +
++ Log4net supports different types of contextual logging and contexts with different scopes. +
+ ++ Contextual data can be set in different scopes. These contexts have progressively narrower visibility. + In the logging event itself the values from all of the contexts are combined together such that + values specified in a lower scoped context hide values from a higher context. +
+ +| Scope | +Type | +Description | +
|---|---|---|
| Global | +log4net.GlobalContext | ++ The global context is shared by all threads in the current AppDomain. + This context is thread safe for use by multiple threads concurrently. + | +
| Thread | +log4net.ThreadContext | ++ The thread context is visible only to the current managed thread. + | +
| Logical Thread | +log4net.ThreadLogicalContext | ++ The logical thread context is visible to a logical thread. Logical + threads can jump from one managed thread to another. For more details + see the .NET API System.Runtime.Remoting.Messaging.CallContext. + | +
| Event | +log4net.Core.LoggingEvent | ++ Each event captures the current contextual state at the time the event + is generated. Contextual data can be set on the event itself. This context + is only visible to the code generating the event itself. + | +
+ The log4net contexts store properties, i.e. name value pairs. The name is a string + the value is any object. A property can be set as follows: +
++log4net.GlobalContext.Properties["name"] = value; +
+ If properties with the same name are set in more than one context scope then + the value in the narrowest scope (lower down in the list above) will hide the + other values. +
++ The property values are stored as objects within the LoggingEvent. + The PatternLayout supports rendering the value of a named + property using the %property{name} syntax. The value is + converted to a string by passing it to the log4net.ObjectRenderer.RendererMap + which will locate any custom renderer for the value type. The default behavior for + custom types is to call the object's ToString() method. +
+ ++ An active property value is one who's value changes over time. +
++ For example, imagine a custom type that implemented the + ToString() method to return the + number of bytes allocated by the runtime garbage collector. +
+
+public class GCAllocatedBytesHelper
+{
+ public override string ToString()
+ {
+ return GC.GetTotalMemory(true).ToString();
+ }
+}+ An instance of this type can be added to the log4net.GlobalContext + during application startup: +
++log4net.GlobalContext.Properties["GCAllocatedBytes"] = new GCAllocatedBytesHelper(); +
+ Once this property is set in the context all subsequent logging events will have a property + called GCAllocatedBytes. The value of the property will be an instance of the + GCAllocatedBytesHelper type. When this value is rendered to a + string by calling the ToString method the current number of bytes + allocated by the garbage collector will be returned and included in the output. +
+ ++ Sometimes simple key value pairs are not the most convenient way of capturing contextual + information. A stack of information is a very convenient way of storing data especially + as our applications tend to be stack based. +
++ The ThreadContext and LogicalThreadContext + also support storing contextual data in a stack. The stack is stored in context property, + therefore stacks have names and more than one stack can exist in the same context. A property + value set in a narrower context would override a stack with the same property name set in a + wider scoped context. +
++ The stack supports Push and Pop methods. + As more contextual data is pushed onto the stack the stack grows. When the stack is rendered + all the data pushed onto the stack is output with the most recent data to the right hand + end of the string. +
++ As the stack is just an object stored in the context properties it is also rendered + using the same PatternLayout syntax: %property{name}. + Where name is the name of the stack. +
++ Calls the the stack's Push and Pop + methods must be matched up so that each push has a corresponding pop. The + Push method also returns an IDisposable + object that will perform the required pop operation when it is disposed. This allows + the C# using syntax to be used to automate the stack management. +
+
+using(log4net.ThreadContext.Stacks["NDC"].Push("context"))
+{
+ log.Info("Message");
+}
++ The INFO level log has a stack stored in its NDC property. The top item in the + stack is the string context. + The using syntax ensures that the value context is popped off the stack + at the end of the block. +
++ The using + syntax is recommended because it removes some work load from the developer and + reduces errors in matching up the Push and Pop calls, especially when exceptions + can occur. +
++ The NDC (Nested Diagnostic Context) exists for compatibility + with older versions of log4net. This helper class implements a stack which is stored + in the thread context property named NDC. +
++ The MDC (MappedDiagnostic Context) exists for compatibility + with older versions of log4net. This helper class implements a properties map which is + mapped directly through to the thread context properties. +
++ To illustrate this point, let us take the example of a web service delivering + content to numerous clients. The web service can build the NDC at the very + beginning of the request before executing other code. The contextual + information can be the client's host name and other information inherent to the + request, typically information contained in cookies. Hence, even if the web + service is serving multiple clients simultaneously, the logs initiated by the + same code, i.e. belonging to the same logger, can still be distinguished + because each client request will have a different NDC stack. Contrast this with + the complexity of passing a freshly instantiated logger to all code exercised + during the client's request. +
++ Nevertheless, some sophisticated applications, such as virtual hosting web + servers, must log differently depending on the virtual host context and also + depending on the software component issuing the request. Log4net supports + multiple logger repositories. This would allow each virtual host to possess its own copy + of the logger hierarchy. Configuring multiple logger hierarchies is beyond the + scope of this document. +
+ +- One of the often-cited arguments against logging is its computational cost. - This is a legitimate concern as even moderately sized applications can generate - thousands of log requests. Much effort was spent measuring and tweaking logging - performance. Log4net claims to be fast and flexible: speed first, flexibility - second. -
-- The user should be aware of the following performance issues. -
-- When logging is turned off entirely or just for a set of levels, the cost of a - log request consists of a method invocation plus an integer comparison. -
-- However, The method invocation involves the "hidden" cost of parameter - construction. -
-- For example, for some logger - log, writing, -
-
-log.Debug("Entry number: " + i + " is " + entry[i].ToString());- incurs the cost of constructing the message parameter, i.e. converting both - integer - i - and - entry[i] - to strings, and concatenating intermediate strings, regardless of whether the - message will be logged or not. This cost of parameter construction can be quite - high and it depends on the number and type of the parameters involved. -
-- To avoid the parameter construction cost write: -
-
-if(log.IsDebugEnabled)
-{
- log.Debug("Entry number: " + i + " is " + entry[i].ToString());
-}- This will not incur the cost of parameter construction if debugging is - disabled. On the other hand, if the logger is debug-enabled, it will incur - twice the cost of evaluating whether the logger is enabled or not: once in - IsDebugEnabled - and once in - Debug. This is an insignificant overhead because - evaluating a logger takes about 1% of the time it takes to actually log. -
-- Certain users resort to pre-processing or compile-time techniques to compile - out all log statements. This leads to perfect performance efficiency with - respect to logging. However, since the resulting application binary does not - contain any log statements, logging cannot be turned on for that binary. In - many people's opinion this is a disproportionate price to pay in exchange for a - small performance gain. -
-- This is essentially the performance of walking the logger hierarchy. When - logging is turned on, log4net still needs to compare the level of the log - request with the level of the request logger. However, loggers may not have an - assigned level; they can inherit them from the logger hierarchy. Thus, before - inheriting a level, the logger may need to search its ancestors. -
-- There has been a serious effort to make this hierarchy walk to be as fast as - possible. For example, child loggers link only to their existing ancestors. In - the - BasicConfigurator - example shown earlier, the logger named - Com.Foo.Bar - is linked directly to the root logger, thereby circumventing the nonexistent - Com - or - Com.Foo - loggers. This significantly improves the speed of the walk, especially in - "sparse" hierarchies. -
-- The typical cost of walking the hierarchy is typically 3 times slower than when - logging is turned off entirely. -
-- This is the cost of formatting the log output and sending it to its target - destination. Here again, a serious effort was made to make layouts (formatters) - perform as quickly as possible. The same is true for appenders. -
-- Although log4net has many features, its first design goal was speed. Some - log4net components have been rewritten many times to improve performance. - Nevertheless, contributors frequently come up with new optimizations. You - should be pleased to know that when configured with the - SimpleLayout - performance tests have shown log4net to log within an order of magnitude of - System.Console.WriteLine. -
-- The following is the series of steps and checks that a messages goes through while being logged. - For the purposes of this example we will document an INFO level - message being logged on logger ConsoleApp.LoggingExample. This logger is configured - to use the log4net.Appender.ConsoleAppender. The repository used - in this example is a log4net.Repository.Hierarchy object. -
-- The user logs a message using the ILog.Info method on the logger - obtained using a call to log4net.LogManager.GetLogger("ConsoleApp.LoggingExample"). - For example: log4net.LogManager.GetLogger("ConsoleApp.LoggingExample").Info("Application Start"); - The ILog interface is actually an extension to log4net that provides level - specific logging methods (i.e. Debug, Info, Warn, Error, and Fatal). -
-- The message is then logged through to the ILogger.Log method on the - appropriate log4net.Repository.Hierarchy.Logger object. The - ILogger.Log method takes the Level to - log at as a parameter and therefore works for all levels. -
-- The repository threshold level is compared to the message level to determine if the message - can be logged. If the message level is below the threshold level the message is not logged. - In this case the repository is a log4net.Repository.Hierarchy object. -
-- The Logger level is compared to the message level to determine if the - message can be logged. Note that the Logger level is inherited from a - parent Logger if not specified explicitly for this Logger. - If the message level is below the Logger level the message is not logged. -
-- A LoggingEvent instance is created to encapsulate the message being logged. -
-- The list of appenders for the Logger is built. This includes appenders - attached to parent Loggers except where excluded by the - Logger.Additivity property. -
-- The LoggingEvent object is passed to the - IAppender.DoAppend method for each appender. -
-- For Each Appender that the LoggingEvent is delivered to the following - actions take place: -
-- The appender threshold level is compared to the message level to determine if the message - can be logged. If the message level is below the threshold level the message is not logged. -
-- If the appender has a filter chain the LoggingEvent is passed down the - filter chain which can decide if the message can be logged or not. -
-- Next an appender specific check is performed. Usually this check will verify that all the - required properties are set for the appender (e.g. a Layout is set if required). -
-- The LoggingEvent is passed to the appender specific - Append method. What happens now is specific to the appender. -
-- The following actions take place in the ConsoleAppender.Append method: -
-- The ConsoleAppender uses a Layout to - format the message as a string for display. -
-- The Layout uses the LoggingEvent.RenderedMessage - property to get the string for the message object. This uses the registered - IObjectRenderer for the type of the message object. -
-- The message text is displayed on the console using the Console.WriteLine method. -
-+ One of the often-cited arguments against logging is its computational cost. + This is a legitimate concern as even moderately sized applications can generate + thousands of log requests. Much effort was spent measuring and tweaking logging + performance. Log4net claims to be fast and flexible: speed first, flexibility + second. +
++ The user should be aware of the following performance issues. +
++ When logging is turned off entirely or just for a set of levels, the cost of a + log request consists of a method invocation plus an integer comparison. +
++ However, The method invocation involves the "hidden" cost of parameter + construction. +
++ For example, for some logger + log, writing, +
+
+log.Debug("Entry number: " + i + " is " + entry[i].ToString());+ incurs the cost of constructing the message parameter, i.e. converting both + integer + i + and + entry[i] + to strings, and concatenating intermediate strings, regardless of whether the + message will be logged or not. This cost of parameter construction can be quite + high and it depends on the number and type of the parameters involved. +
++ To avoid the parameter construction cost write: +
+
+if(log.IsDebugEnabled)
+{
+ log.Debug("Entry number: " + i + " is " + entry[i].ToString());
+}+ This will not incur the cost of parameter construction if debugging is + disabled. On the other hand, if the logger is debug-enabled, it will incur + twice the cost of evaluating whether the logger is enabled or not: once in + IsDebugEnabled + and once in + Debug. This is an insignificant overhead because + evaluating a logger takes about 1% of the time it takes to actually log. +
++ Certain users resort to pre-processing or compile-time techniques to compile + out all log statements. This leads to perfect performance efficiency with + respect to logging. However, since the resulting application binary does not + contain any log statements, logging cannot be turned on for that binary. In + many people's opinion this is a disproportionate price to pay in exchange for a + small performance gain. +
++ This is essentially the performance of walking the logger hierarchy. When + logging is turned on, log4net still needs to compare the level of the log + request with the level of the request logger. However, loggers may not have an + assigned level; they can inherit them from the logger hierarchy. Thus, before + inheriting a level, the logger may need to search its ancestors. +
++ There has been a serious effort to make this hierarchy walk to be as fast as + possible. For example, child loggers link only to their existing ancestors. In + the + BasicConfigurator + example shown earlier, the logger named + Com.Foo.Bar + is linked directly to the root logger, thereby circumventing the nonexistent + Com + or + Com.Foo + loggers. This significantly improves the speed of the walk, especially in + "sparse" hierarchies. +
++ The typical cost of walking the hierarchy is typically 3 times slower than when + logging is turned off entirely. +
++ This is the cost of formatting the log output and sending it to its target + destination. Here again, a serious effort was made to make layouts (formatters) + perform as quickly as possible. The same is true for appenders. +
++ Although log4net has many features, its first design goal was speed. Some + log4net components have been rewritten many times to improve performance. + Nevertheless, contributors frequently come up with new optimizations. You + should be pleased to know that when configured with the + SimpleLayout + performance tests have shown log4net to log within an order of magnitude of + System.Console.WriteLine. +
++ The following is the series of steps and checks that a messages goes through while being logged. + For the purposes of this example we will document an INFO level + message being logged on logger ConsoleApp.LoggingExample. This logger is configured + to use the log4net.Appender.ConsoleAppender. The repository used + in this example is a log4net.Repository.Hierarchy object. +
++ The user logs a message using the ILog.Info method on the logger + obtained using a call to log4net.LogManager.GetLogger("ConsoleApp.LoggingExample"). + For example: log4net.LogManager.GetLogger("ConsoleApp.LoggingExample").Info("Application Start"); + The ILog interface is actually an extension to log4net that provides level + specific logging methods (i.e. Debug, Info, Warn, Error, and Fatal). +
++ The message is then logged through to the ILogger.Log method on the + appropriate log4net.Repository.Hierarchy.Logger object. The + ILogger.Log method takes the Level to + log at as a parameter and therefore works for all levels. +
++ The repository threshold level is compared to the message level to determine if the message + can be logged. If the message level is below the threshold level the message is not logged. + In this case the repository is a log4net.Repository.Hierarchy object. +
++ The Logger level is compared to the message level to determine if the + message can be logged. Note that the Logger level is inherited from a + parent Logger if not specified explicitly for this Logger. + If the message level is below the Logger level the message is not logged. +
++ A LoggingEvent instance is created to encapsulate the message being logged. +
++ The list of appenders for the Logger is built. This includes appenders + attached to parent Loggers except where excluded by the + Logger.Additivity property. +
++ The LoggingEvent object is passed to the + IAppender.DoAppend method for each appender. +
++ For Each Appender that the LoggingEvent is delivered to the following + actions take place: +
++ The appender threshold level is compared to the message level to determine if the message + can be logged. If the message level is below the threshold level the message is not logged. +
++ If the appender has a filter chain the LoggingEvent is passed down the + filter chain which can decide if the message can be logged or not. +
++ Next an appender specific check is performed. Usually this check will verify that all the + required properties are set for the appender (e.g. a Layout is set if required). +
++ The LoggingEvent is passed to the appender specific + Append method. What happens now is specific to the appender. +
++ The following actions take place in the ConsoleAppender.Append method: +
++ The ConsoleAppender uses a Layout to + format the message as a string for display. +
++ The Layout uses the LoggingEvent.RenderedMessage + property to get the string for the message object. This uses the registered + IObjectRenderer for the type of the message object. +
++ The message text is displayed on the console using the Console.WriteLine method. +
+