log4net.tools.integration

Tools for log4net: - MetricsCsvWriter writes logging metrics in a csv file.


Keywords
log4net, integration, csv
License
MIT
Install
Install-Package log4net.tools.integration -Version 1.0.1

Documentation

About log4net Tools

The project was designed to supplement the log4net base functionality with often demanded structure blocks like appenders, log parsers and handlers.

Latest Builds:

  • log4net.tools
  • log4net.tools.integration

ForwardingAppenderAsync

The ForwardingAppenderAsync wrapps any log4net appender putting the async buffer in front. The independent background worker is responsible for dequeuing of items from the buffer without blocking a client app.

Functional blocks

Thus waiting needing before for example to write a log in a database is delegated now and the only place where the client app is blocking is the stage of the in-memory enqueuing.

latency

The 'Dequeue' graph reflects the latency in microseconds of the RollingFileAppender (taken just as example) which works under the hood as the attached synchronous appender. A consumer is blocked only during the 'Enqueue' microseconds.

The approach allows:

  • to get the minimal blocking of the client app;
  • to turn any 'old' synchronous appender into the 'async' version easily without additional coding or recompile;
  • to eliminate concurrent waits on the internal lock section as the background worker is singlethreaded if no pooling is used;
  • to build aggregations over the buffer. For example, to drop log duplicates or generate stats on the fly.

Configurable logic:

XML Configuration

The example of the minimal configuration:

<appender name="ForwardingAppenderAsync" type="log4net.tools.ForwardingAppenderAsync">
    <appender-ref ref="RollingFileAppender" />
</appender>

The example of the advanced configuration:

<appender name="ForwardingAppenderAsync" type="log4net.tools.ForwardingAppenderAsync">
    <BufferSize value="1000"/>
    <Fix value="260"/>
    <BufferOverflowBehaviour value="RejectNew"/>
    <BufferClosingType value="DumpToLog"/>
    <WorkerPoolSize value="5"/>

    <appender-ref ref="DebugAppender" />
    <appender-ref ref="RollingFileAppender" />
    <appender-ref ref="AdoNetAppender" />
</appender>

More examples of the xml configuration are available here.

RollingFileAppender Benchmark

10K of sequential info-logs:

Method Mean
RollingFileAppender 1,742.69 ms
Buffered RollingFileAppender 180.728 ms
Forwarded RollingFileAppender 5.43 ms

10K of "parallel" (Parallel.For) info-logs:

Method Mean
RollingFileAppender 1,668.64 ms
Buffered RollingFileAppender 254.72 ms
Forwarded RollingFileAppender 4.45 ms

AdoNetAppender Benchmark

10K of sequential info-logs:

Method Mean
AdoNetAppender 3,336.11 ms
Forwarded AdoNetAppender 5.54 ms

10K of "parallel" (Parallel.For) info-logs:

Method Mean
AdoNetAppender 2,797.39 ms
Forwarded AdoNetAppender 4.62 ms

Worker Pool

The worker pool allows to improve throughput between the buffer and the attached appenders as it allows to dequeue the cached logs in parallel.

For example, the test with the RollingFileAppender shows the difference in intencity of 'dequeue' events: 1vs5_workers_rps

The latency is on the same level. We observe that more workers generate the denser 'Dequeue' graph. 1vs5_workers_latency

The buffer size grows not as steep as with the single threaded configuration as several workers together are more productive in processing of the benchmark stress load. 1vs5_workers_buffer

The 'WorkerPoolSize' configuration property defines the level of parallelism. The default value is '1' which corresponds to the 'single worker' scenario.

ForwardingAppenderAsyncWithMetrics

The appender grabs the metrics: LatencyUs, BufferSize, AllocatedBytes in addition to the ForwardingAppenderAsync functionality. The default output is Trace Info. Metrics bring some additional load so it is recommended to use the ForwardingAppenderAsync in scenarios where the minimum latency is required.

The example of the minimal xml configuration:

<appender name="Forwarding2RollingFileAppenderWithMetrics" type="log4net.tools.ForwardingAppenderAsyncWithMetrics, log4net.tools">
    <appender-ref ref="RollingFileAppender" />
</appender>

The example above uses "Trace" channel to output the metrics.

The example of the advanced xml configuration:

<appender name="Forwarding2RollingFileAppenderWithMetrics" type="log4net.tools.ForwardingAppenderAsyncWithMetrics, log4net.tools">
    <MetricsWriter type="log4net.tools.integration.MetricsCsvWriter, log4net.tools.integration">
        <CsvFilePath value="data.csv"/>
        <MaxRowCount value="100000"/>
    </MetricsWriter> 

    <BufferSize value="1000"/>
    <Fix value="260"/>
    <BufferOverflowBehaviour value="RejectNew"/>
    <BufferClosingType value="DumpToLog"/>
    <WorkerPoolSize value="5"/>

    <appender-ref ref="DebugAppender" />
    <appender-ref ref="RollingFileAppender" />
    <appender-ref ref="AdoNetAppender" />
</appender>

MetricsCsvWriter is available in the log4net.tools.integration package.

The example of the output:

DateTime            ,LatencyUs ,BufferSize ,CallerName ,AllocatedBytes
2021-05-04T11:49:22 ,2.00      ,76         ,DoAppend   ,5491168
2021-05-04T11:49:22 ,2.80      ,77         ,DoAppend   ,5587296
2021-05-04T11:49:22 ,318.80    ,77         ,Dequeue    ,5684840
2021-05-04T11:49:22 ,2.40      ,77         ,DoAppend   ,1269424
2021-05-04T11:49:22 ,2.50      ,78         ,DoAppend   ,1367776
2021-05-04T11:49:22 ,2.00      ,79         ,DoAppend   ,1466128
2021-05-04T11:49:22 ,2.30      ,80         ,DoAppend   ,1564480
2021-05-04T11:49:22 ,1.50      ,81         ,DoAppend   ,1662832
2021-05-04T11:49:22 ,273.80    ,81         ,Dequeue    ,1752992

The python notebook to analyze the metrics.

Log Analyzer

It's the python script which parses log4net logs and returns the stats related to the log levels and error messages.

import pprint
from colorama import Fore, init
from simple_log_parser import SimpleLogParser

error_stats = SimpleLogParser('./log.txt').errors_count(from_date='2021-04-15')

init(autoreset=True)
print(Fore.GREEN + 'Error Levels:')
pprint.pprint(error_stats[0])
print(Fore.GREEN + 'Error Messages:')
pprint.pprint(error_stats[1])

The code above prints this:

Error Levels:
defaultdict(<class 'int'>, {'ERROR': 6})

Error Messages:
defaultdict(<class 'int'>,
            {'Microsoft.AspNetCore.Connections.ConnectionResetException: The client has disconnected\n': 1,
             "System.ArgumentException: 'A' is invalid": 1,
             "System.ArgumentException: 'B' cannot be > 4": 1,
             "System.Data.SqlClient.SqlException (0x80131904): Error 2601, Level 14, State 1, Procedure ...": 1,
             'System.NotImplementedException: The method or operation is not implemented.\n': 2})