Log::Log4perl::Layout::PatternLayout::Elapsed - Logs the time elapsed between the last log event
From a log4perl configuration file:
log4perl.rootLogger = ALL, DEV, FILE # Colored console with PatternLayout::Elapsed log4perl.appender.DEV = Log::Log4perl::Appender::ScreenColoredLevels log4perl.appender.DEV.layout = Log::Log4perl::Layout::PatternLayout::Elapsed log4perl.appender.DEV.layout.ConversionPattern = %5Rms %-5p %m [%M:%L]%n log4perl.appender.DEV.Threshold = ALL # Log file with timestamps and elapsed time log4perl.appender.FILE = Log::Dispatch::FileRotate log4perl.appender.FILE.filename = 'logs/app.log' log4perl.appender.FILE.Threshold = ALL # Using both an the time elapsed since the begining and the last event log4perl.appender.FILE.layout = Log::Log4perl::Layout::PatternLayout::Elapsed log4perl.appender.FILE.layout.ConversionPattern = %d{ISO8601} (%5rms) %-5p [%-12c] %C{2} %M:%L - %m [%5Rms]%n
Through Perl code (why would you do that?):
use Log::Log4perl::Layout::PatternLayout::Elapsed; my $layout = Log::Log4perl::Layout::PatternLayout::Elapsed->new( '%5Rms %-5p %m [%M:%L]%n' );
NOTE: Log::Log4perl 1.25 includes already the functionality of this module in Log::Log4perl::Layout::PatternLayout. It's strongly suggested that you use Log::Log4perl's implementation as it fixes some consistency issues when mixing %r and %R in the same logging message. If you can't upgrade to Log::Log4perl 1.25 or higher then you should be able to use this module and enjoy the same functionality.
This layout adds the placeholder %R, which is used to display the time elapsed between two consecutive logging events. In the case of the first logging event the time elapsed since the beginning of the application will be displayed.
%R
This module is a sub class of Log::Log4perl::Layout::PatternLayout, which means that it implements that same formats and can used the same placeholders. The module Log::Log4perl::Layout::PatternLayout is in turn based on http://jakarta.apache.org/log4j/docs/api/org/apache/log4j/PatternLayout.html.
The new() method creates a new PatternLayout, specifying its log format. The format string supports all placeholders implemented by Log::Log4perl::Layout::PatternLayout, with the addition of the new placeholder:
new()
%R Number of milliseconds elapsed since the last logging event
This module is implemented in order to ensure that each appender will track it's own elapsed time. This way the time displayed is truly the time spent between two consecutive log events for each appender. Thus if different thresholds are applied to two appenders logging in the same application it's normal if they both show different values for the time elapsed for a same log statement. This is because the previous logging message might have not been issued at the same time due to the different thresholds.
Therefore the following Perl code:
use Time::HiRes qw(sleep); INFO "Start"; sleep 0.1; DEBUG "Pause: 0.1 sec"; sleep 1.5; INFO "Pause: 1.5 secs"; sleep 0.5; DEBUG "Pause: 0.5 sec"; WARN "End";
When executed with the following Log4perl configuration:
log4perl.rootLogger = ALL, A, B log4perl.appender.A = Log::Log4perl::Appender::Screen log4perl.appender.A.layout = Log::Log4perl::Layout::PatternLayout::Elapsed log4perl.appender.A.layout.ConversionPattern = %5rms %-5p A %5Rms %m%n log4perl.appender.A.Threshold = ALL log4perl.appender.B = Log::Log4perl::Appender::Screen log4perl.appender.B.layout = Log::Log4perl::Layout::PatternLayout::Elapsed log4perl.appender.B.layout.ConversionPattern = B %5Rms %m%n log4perl.appender.B.Threshold = INFO
Will produce the following results (output merged side by side manually):
%r %p Logger %R %m Logger %R %m 44ms INFO A 0ms Start | B 0ms Start 144ms DEBUG A 100ms Pause: 0.1 sec | 1644ms INFO A 1500ms Pause: 1.5 secs | B 1600ms Pause: 1.5 secs 2144ms DEBUG A 500ms Pause: 0.5 sec | 2145ms WARN A 1ms End | B 501ms End
When a program is taking a long time to execute the first instinct is to check the logs and to find which logging statements where issued after the hotspot.
The problem is that the time elapsed between to logging events is not directly available in the logs. This value needs to be computed, usually by another program by subtracting the times logged between to consecutive logging events. This can be tedious as log patterns can change and might not always be on a single line. In fact, in a single application different appenders might even use different patterns and different thresholds.
That's why this Perl module was created. Now the time elapsed between two consecutive log events can be automatically inserted into the log statement. This is now performed by Log4perl and doesn't require an external script in order to compute the values.
This module defines the following methods:
This is the class constructor it ensures that the placeholder %R is handled by Log4perl.
Compute the value for the placeholder %R.
If %d, %r or %R are used simultaneously it could happen that the values don't match within a single logging statement. This is because Log4perl computes the current time for each placeholder and the time can change between the different invocations of the clock's time.
NOTE: This bugs is fixed in Log::Log4perl 1.25.
Log::Log4perl::Layout::PatternLayout distributed with Log::Log4perl 1.25 or higher.
Emmanuel Rodriguez, <emmanuel.rodriguez@gmail.com>.
Copyright (C) 2008 by Emmanuel Rodriguez
This library is free software; you can redistribute it and/or modify it under the same terms as Perl itself, either Perl version 5.8.8 or, at your option, any later version of Perl 5 you may have available.
To install Log::Log4perl::Layout::PatternLayout::Elapsed, copy and paste the appropriate command in to your terminal.
cpanm
cpanm Log::Log4perl::Layout::PatternLayout::Elapsed
CPAN shell
perl -MCPAN -e shell install Log::Log4perl::Layout::PatternLayout::Elapsed
For more information on module installation, please visit the detailed CPAN module installation guide.