- - - -

Apache log4net™ Manual - Contexts

- 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. -

- -

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. -

- -

Context Properties

- 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. -

- -

Active Property Values

- 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. -

- -

Context Stacks

- 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. -

- -

Nested Diagnostic Contexts

- 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. -

- -

Mapped Diagnostic Contexts

- 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. -

- -

- + + + +

Apache log4net™ Manual - Contexts

+ 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. +

+ +

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. +

+ +

Context Properties

+ 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. +

+ +

Active Property Values

+ 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. +

+ +

Context Stacks

+ 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. +

+ +

Nested Diagnostic Contexts

+ 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. +

+ +

Mapped Diagnostic Contexts

+ 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. +

+ +

- - - -

Apache log4net™ Manual - Internals

Performance

- 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. -

- Logging performance when logging is turned off. -
- 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. -
-
- The performance of deciding whether to log or not to log when logging is - turned on. -
- 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. -
-
- Actually outputting log messages -
- 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. -

- -

Logging Event Flow

- 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. -
-

- -

- + + + +

Apache log4net™ Manual - Internals

Performance

+ 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. +

+ Logging performance when logging is turned off. +
+ 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. +
+
+ The performance of deciding whether to log or not to log when logging is + turned on. +
+ 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. +
+
+ Actually outputting log messages +
+ 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. +

+ +

Logging Event Flow

+ 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. +
+

+ +