Detailed logger

From Sense/Net Wiki
Jump to: navigation, search
  •  
  •  
  •  
  •  
  • 100%
  • 6.4 obsolete
  • Enterprise
  • Community
  • Planned

Overview

Logging
Sense/Net ECM has a robust Logging system built on Microsoft Enterprise Library. There are cases however when a few entries in the event log is not enough to track down an error related to heavy load or resource bottleneck. In that case you may turn on the DetailedLogger feature that provides more detailed information for operators and developers about events happening under the hood.

Please note that from version 6.5.3 Patch 4 the DetailedLogger module is no longer available: it has been replaced by the easy-to-use SnTrace API.

Details

Detailed logger gathers detailed log messages from different threads and writes a batch of lines regularly to the file system. It places a log file to the following directory under the web folder:

  • App_Data\\DetailedLog

After a configured number of lines a new log file will be opened - see the configuration section below.

Logged events

In the core Sense/Net ECM product there are many places where we log events using the detaild logger. The following list is extended constantly as we add new log lines:

  • Application start and end
  • PotralContext module: OnEnter and OnEndRequest
  • Content queries that were initiated and executed
  • Lucene manager: index open/write and shutdown operations
  • Content Repository shut down
  • Service shut down events

Performance

In the Sesne/Net ECM core product the logger methods and their calls are conditionally compiled. This means the logger calls are not even present in release libraries used in production environment. Please see the details of switching this feature on later in this article.

Log lines are stored temporarily in a central buffer and written in batches to the file system for performance reasons. In case of a process kill or thread abourt this could lead to missing lines but leads to a significantly more stable and faster logging.

Logging modes

There are two different logging modes that result in different log lines in the log file.

Event logging

This is a simple log line containing a message:

3052	2014-08-13 04:01:25.86417	T:50	PCM.OnEndRequest GET http://localhost/features
>3053	2014-08-13 04:01:26.65225	T:62	PCM.OnEnter http://localhost/features/gallery/

Columns

  • >: Signs the first line of a batch writing.
  • Count: simple line counter. It is possible that some lines won't be in the right order due to the buffer.
  • Timestamp: Time of calling the logger method.
  • Thread id: identifier of the caller thread.
  • Message: the message text filled with the given parameters.

Example

In source code you can write a log line like this:

DetailedLogger.Log("Shutting down {0}", svc.GetType().Name);

Please note that due to conditional compiling the line above will only be compiled into the library when needed. So it is advisable that you do not do information gathering outside of this method call. Put all the necessary formatting and collecting code inside the method call's parameter list so it does not slow down release libraries.

Operation logging

This mode is for monitoring the execution flow of important methods: you can place START and END logger calls wherever you want to track the execution.

>3003	2014-08-12 21:16:05.85041	T:64	Op:147 START	ContentQuery WorkflowStatus:Running .AUTOFILTERS:OFF | Top:0 Skip:0 Sort:
3004	2014-08-12 21:16:05.85141	T:64	Op:148 START	LucQuery.Execute WorkflowStatus:running | Top:2147483647 Skip:0 Sort:
3005	2014-08-12 21:16:05.85141	T:64	Op:148 END (00:00:00)	LucQuery.Execute WorkflowStatus:running | Top:2147483647 Skip:0 Sort:
3006	2014-08-12 21:16:05.85141	T:64	Op:147 END (00:00:00.0010001)	ContentQuery WorkflowStatus:Running .AUTOFILTERS:OFF | Top:0 Skip:0 Sort:

Columns

Additionally to the columns seen in the previous section, the operation mode has a few more:

  • Operation Id: unique identifier of the operation for exploring nested events and other overlapping operations.
  • Operation verb: "START" or "END".
  • Operation duration: Time elapsed between the "START" and "END" calls.

Example

// create operation frame
var op = DetailedLogger.CreateOperation();
// start the operation frame and write a start message
DetailedLogger.Log(op, "Application_End");
// the relevant operation
SenseNet.ContentRepository.Repository.Shutdown();
// finish operation frame. Logger writes the "END" message and duration.
op.Finish();

Switch detailed logger ON

The logger methods and their calls are conditionally compiled in Sense/Net ECM. We have a custom conditional symbol for this feature:

  • DIAGNOSTIC

This means that the detailed logger can be switched on by using a different assembly set, that was compiled with the Diagnostic solution configuration.

Sense/Net ECM libraries

  1. Open the core product solution in Visual Studio 2013.
  2. Change the solution configuration to Diagnostic.
    Diagnostic solution configuration
  3. Compile the solution, deploy & start the portal.
  4. Review the log file(s) in the app data folder mentioned above.

3rd party libraries

If you want to use the detailed logger in your custom libraries, you need to create a "Diagnostic" configuration for every project where you want to place DetailedLogger calls.

  1. Open your solution in Visual Studio 2013.
  2. In Solution Explorer right click on the solution and select "Configuration Manager...".
    Open Configuration Manager
  3. Create new solution configuration.
    New solution configuration
  4. Name it "Diagnostic", select "Release" from the dropdown, check "Create new project configurations".
    New configuration
  5. Open the properties window of your project in Solution Explorer.
    Open project properties
  6. Select the Build tab, ensure that Diagnostic is selected as Configuration and write "DIAGNOSTIC" into the Conditional compilation symbols textbox.
    Properties window
  7. Compile the solution, deploy & start the portal.

Buffering

The logger writes the lines to the file system through a line buffer. This solution increases the logging performance because the caller methods spend significally shorter time in the log method. A longer buffer means safer execution but larger memory footprint.

If the buffer is too small, the logger writes an error line:

>BUFFER OVERRUN ERROR: Buffer size is 100, unwritten lines : 185
243	2014-08-13 06:01:54.23410	T:14	WorkerB 5 (immediately)

The buffer size is not increased automatically, but you can configure it manually.

Logger tracing

After every 1000th line the logger writes a trace line that contains some logger-related information. Trace line frequency can be configured. By default the line contains only the buffer usage.

3052	2014-08-13 04:01:25.86417	T:50	PCM.OnEndRequest GET http://localhost/features
MaxPdiff: 31

In case you want to see more details, you need to define the DEBUG symbol on the SenseNet.Storage project (that is where DetailedLogger resides).

3052	2014-08-13 04:01:25.86417	T:50	PCM.OnEndRequest GET http://localhost/features
MaxPdiff: 112, MaxLog: 1197, PeakLog: 1183, MaxWrite: 11380, PeakWrite: 5771

The trace line contains the following columns:

  • MaxPdiff: Buffer usage between two writes.
  • MaxLog: Longest time in the log method in ticks.
  • PeakLog: Peak time in the log method in ticks.
  • MaxWrite: Longest time in the file writer method in ticks.
  • PeakWrite: Peak time in the file writer method in ticks.

Configuration

You can fine-tune the behavior of the detailed logger by modifying the value of the following configuration items in the web.config.

  • BufferSize: Allocated line buffer. Default: 10000.
  • WriteToFileDelay: Time between end of previous and start of next writing in milliseconds. Default: 1000.
  • MaxWritesInOneFile: Number of writes into a single file. Default: 100. After this a new log file will be created.
  • LinesPerTrace: Frequency of writing information about the state of the detailed logger to the log. Default: 1000.
<sensenet>
	<detailedLogger>
      <add key="BufferSize" value="10000" />
      <add key="WriteToFileDelay" value="1000" />
      <add key="MaxWritesInOneFile" value="100" />
      <add key="LinesPerTrace" value="1000" />
    </detailedLogger>
</sensenet>

Related links

References

There are no external references for this article.