Add benchmarking tests to MooseX::Log::Log4perl to verify overhead
Random May 20th, 2009
After a while I had the chance to get back to MooseX::Log::Log4perl, which is Role (based on Moose) that can be easily reused in classes requiring logging functionality.
While it is really simple to use, I still found myself often directly using the default logger approach by creating a class variable and using that. So instead of:
use Moose;
with MooseX::Log::Log4perl;
sub whatever {
my $self = shift;
$self->log->debug("Here I am") if $self->log->is_debug;
}
mostly the direct logger was used in the classes.
use Log::Log4perl;
use vars qw($log);
$log = Log::Log4perl->get_logger(__PACKAGE__);
sub whatever {
my $self = shift;
$log->debug("Here I am") if $log->is_debug;
}
One reason was that during that time I optimized for speed and found a hotspot to be the additional method call for the “log” method. As perl has some overhead in calling functions, this still holds true to some extend, so that’s why I added a benchmarking test to the testsuite of MooseX::Log::Log4perl.
So if you have the chance, I’d like to see if in your test environment still the performance limits (keep overhead lower than 5% compared to using Log::Log4perl directly). To run the test simply get the sources and run the test.
cpan> look MooseX::Log::Log4perl
shell# TEST_MAINT=1 prove -l -v t/99_bench.t
t/99bench.t ..
1..6
ok 1 - Bench instance for MooseX::Log::Log4perl isa BenchMooseXLogLog4perl
ok 2 - Bench instance for Log::Log4perl isa BenchLogLog4perl
Rate MooseX-L4p log MooseX-L4p logger Log4perl method Log4perl direct
MooseX-L4p log 21235/s -- -0% -4% -6%
MooseX-L4p logger 21273/s 0% -- -4% -6%
Log4perl method 22102/s 4% 4% -- -2%
Log4perl direct 22535/s 6% 6% 2% --
...
If all tests pass you stayed within the limits (around 95% compared to using Log4perl directly). I’d like to see your results. So please comment on it and add the comparison table to it.
- Category: Bits & Bytes S-Tags: CPAN, Moose, Perl
- Comments(7)
Here are my results.
perl, v5.10.0 built for i486-linux-gnu-thread-multi
Rate MooseX-L4p log MooseX-L4p logger Log4perl method Log4perl direct
MooseX-L4p log 22046/s — -1% -4% -6%
MooseX-L4p logger 22293/s 1% — -3% -5%
Log4perl method 22996/s 4% 3% — -2%
Log4perl direct 23442/s 6% 5% 2% —
Tests 4 to 6 fail.
Hi
My results are:
ron@zoe:~/perl.modules/MooseX-Log-Log4perl-0.40$ TEST_MAINT=1 prove -v -l t/99bench.t
t/99bench……
1..6
ok 1 – Bench instance for MooseX::Log::Log4perl isa BenchMooseXLogLog4perl
ok 2 – Bench instance for Log::Log4perl isa BenchLogLog4perl
Rate Log4perl method Log4perl direct MooseX-L4p log MooseX-L4p logger
Log4perl method 11480/s — -10% -11% -14%
Log4perl direct 12755/s 11% — -1% -5%
MooseX-L4p log 12937/s 13% 1% — -4%
MooseX-L4p logger 13411/s 17% 5% 4% —
ok 3 – Call rate of ->logger must be above 96% (13411 / 12755 = 105.14 %) to Log4perl direct
ok 4 – Call rate of ->log must be above 95% (13411 / 12755 = 101.43 %) to Log4perl direct
ok 5 – Call rate of ->logger must be above 98% (13411 / 11480 = 116.82 %) to Log4perl via method
ok 6 – Call rate of ->log must be above 97% (13411 / 11480 = 112.69 %) to Log4perl via method
ok
All tests successful.
Files=1, Tests=6, 52 wallclock secs ( 0.02 usr 0.01 sys + 52.14 cusr 0.14 csys = 52.31 CPU)
Result: PASS
Here goes:
$ TEST_MAINT=1 prove -l -v t/99bench.t
t/99bench….1..6
ok 1 – Bench instance for MooseX::Log::Log4perl isa BenchMooseXLogLog4perl
ok 2 – Bench instance for Log::Log4perl isa BenchLogLog4perl
Rate MooseX-L4p log MooseX-L4p logger Log4perl method Log4perl direct
MooseX-L4p log 13796/s — -2% -6% -9%
MooseX-L4p logger 14091/s 2% — -4% -7%
Log4perl method 14700/s 7% 4% — -3%
Log4perl direct 15109/s 10% 7% 3% —
not ok 3 – Call rate of ->logger must be above 96% (14091 / 15109 = 93.26 %) to Log4perl direct
# Failed test ‘Call rate of ->logger must be above 96% (14091 / 15109 = 93.26 %) to Log4perl direct’
# at t/99bench.t line 98.
not ok 4 – Call rate of ->log must be above 95% (14091 / 15109 = 91.31 %) to Log4perl direct
# Failed test ‘Call rate of ->log must be above 95% (14091 / 15109 = 91.31 %) to Log4perl direct’
# at t/99bench.t line 101.
not ok 5 – Call rate of ->logger must be above 98% (14091 / 14700 = 95.86 %) to Log4perl via method
# Failed test ‘Call rate of ->logger must be above 98% (14091 / 14700 = 95.86 %) to Log4perl via method’
# at t/99bench.t line 105.
not ok 6 – Call rate of ->log must be above 97% (14091 / 14700 = 93.85 %) to Log4perl via method
# Failed test ‘Call rate of ->log must be above 97% (14091 / 14700 = 93.85 %) to Log4perl via method’
# at t/99bench.t line 108.
# Looks like you failed 4 tests of 6.
dubious
Test returned status 4 (wstat 1024, 0x400)
DIED. FAILED tests 3-6
Failed 4/6 tests, 33.33% okay
Failed Test Stat Wstat Total Fail List of Failed
——————————————————————————-
t/99bench.t 4 1024 6 4 3-6
Failed 1/1 test scripts. 4/6 subtests failed.
Files=1, Tests=6, 59 wallclock secs (48.89 cusr + 0.12 csys = 49.01 CPU)
Failed 1/1 test programs. 4/6 subtests failed.
$ perl -V
Summary of my perl5 (revision 5 version 10 subversion 0) configuration:
Platform:
osname=linux, osvers=2.6.22-gentoo-r2enkidu, archname=i686-linux-thread-multi
uname=’linux enkidu 2.6.22-gentoo-r2enkidu #2 preempt mon aug 20 23:42:52 edt 2007 i686 amd sempron(tm) processor 3100+ authenticamd gnulinux ‘
config_args=”
hint=recommended, useposix=true, d_sigaction=define
useithreads=define, usemultiplicity=define
useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef
use64bitint=undef, use64bitall=undef, uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler:
cc=’cc’, ccflags =’-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64′,
optimize=’-O2′,
cppflags=’-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -I/usr/local/include’
ccversion=”, gccversion=’4.1.2 (Gentoo 4.1.2 p1.0.1)’, gccosandvers=”
intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12
ivtype=’long’, ivsize=4, nvtype=’double’, nvsize=8, Off_t=’off_t’, lseeksize=8
alignbytes=4, prototype=define
Linker and Libraries:
ld=’cc’, ldflags =’ -L/usr/local/lib’
libpth=/usr/local/lib /lib /usr/lib
libs=-lnsl -lndbm -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -lc
perllibs=-lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
libc=/lib/libc-2.6.1.so, so=so, useshrplib=false, libperl=libperl.a
gnulibc_version=’2.6.1′
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags=’-Wl,-E’
cccdlflags=’-fPIC’, lddlflags=’-shared -O2 -L/usr/local/lib’
Characteristics of this binary (from libperl):
Compile-time options: MULTIPLICITY PERL_DONT_CREATE_GVSV
PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP USE_ITHREADS
USE_LARGE_FILES USE_PERLIO USE_REENTRANT_API
Built under linux
Compiled at Nov 26 2008 15:22:43
%ENV:
PERL5_CPANPLUS_IS_RUNNING=”5571″
PERL5_CPAN_IS_RUNNING=”5571″
@INC:
/usr/local/lib/perl5/5.10.0/i686-linux
/usr/local/lib/perl5/5.10.0
/usr/local/lib/perl5/site_perl/5.10.0/i686-linux
/usr/local/lib/perl5/site_perl/5.10.0
/usr/local/lib/perl5/site_perl/5.8.6
/usr/local/lib/perl5/site_perl
WinXP, Strawberry Perl 5.10.0. Test passed.
Rate MooseX-L4p log Log4perl method MooseX-L4p logger Log4perl direct
MooseX-L4p log 5697/s — -1% -1% -3%
Log4perl method 5734/s 1% — -0% -2%
MooseX-L4p logger 5753/s 1% 0% — -2%
Log4perl direct 5872/s 3% 2% 2% —
Here are the results for my Windows XP system running Strawberry Perl 5.10.0.5:
C:\strawberry\cpan\build\MooseX-Log-Log4perl-0.40-HkWkV3>prove -v -l t/99bench.t
t/99bench.t ..
1..6
ok 1 – Bench instance for MooseX::Log::Log4perl isa BenchMooseXLogLog4perl
ok 2 – Bench instance for Log::Log4perl isa BenchLogLog4perl
Rate MooseX-L4p log MooseX-L4p logger Log4perl method Log4p
erl direct
MooseX-L4p log 20977/s — -2% -3%
-5%# Failed test ‘Call rate of ->log must be above 95% (21311 / 22127 =
94.80 %) to Log4perl direct’
# at t/99bench.t line 101.
MooseX-L4p logger 21311/s 2% — -1%
-4%
Log4perl method 21571/s 3% 1% —
-3%
Log4perl direct 22127/s 5% 4% 3%
–# Looks like you failed 1 test of 6.
ok 3 – Call rate of ->logger must be above 96% (21311 / 22127 = 96.31 %) to Log4
perl direct
not ok 4 – Call rate of ->log must be above 95% (21311 / 22127 = 94.80 %) to Log
4perl direct
ok 5 – Call rate of ->logger must be above 98% (21311 / 21571 = 98.79 %) to Log4
perl via method
ok 6 – Call rate of ->log must be above 97% (21311 / 21571 = 97.25 %) to Log4per
l via method
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/6 subtests
Test Summary Report
——————-
t/99bench.t (Wstat: 256 Tests: 6 Failed: 1)
Failed test: 4
Non-zero exit status: 1
Files=1, Tests=6, 51 wallclock secs ( 0.03 usr + 0.01 sys = 0.05 CPU)
Result: FAIL
Thanks to all who posted their results so far!
Interesting to see that perl method call overhead seems to be varying a lot on different platforms. It seems like older CPUs or memory have a negative effect (guess it’s mostly CPU extensions which are not available). Seems like the self-compiled gentoo (which was also probably running on very nostalgic hardware as it only had 14000/s) had the worst values I ever saw.
Most interesting were the results of Ron Savage, which even indicated that MooseX::Log::Log4perl is even faster then using Log4perl direct, never thought I implemented it that good ;-)
Any comments if that speed hit is worth having cleaner code and especially how much is ok, would be appriciated…
Personally I would take 5% speed hit if coding a non-realtime app, but not more, as I see it as a waste of resources then, and risk getting into trouble sooner, if my app grows…
This is on a 3GHz Core2 Duo running Mac OS X 10.5.3:
Rate MooseX-L4p log MooseX-L4p logger Log4perl method Log4perl direct
MooseX-L4p log 28006/s — -3% -4% -6%
MooseX-L4p logger 28792/s 3% — -2% -4%
Log4perl method 29305/s 5% 2% — -2%
Log4perl direct 29861/s 7% 4% 2% —