Log::Log4perl speed with and without sub { ... }

log4perl-speed.pl

#!/usr/bin/env perl

use strict;
use warnings;

use Log::Log4perl qw(:easy);
use Data::Dumper;
use Time::HiRes;
use Readonly;

Log::Log4perl->easy_init( $DEBUG ); # so trace() won't be printed

my $logger = get_logger();


sub test_variable()
{
    my $variable = 'Keeping Up with the Kardashians';

    Readonly my $iterations => 1_000_000;

    my ( $start, $end );

    $logger->info('Testing variable without sub{} hack...');
    $start = Time::HiRes::gettimeofday();
    for ( my $x = 0; $x < $iterations; ++$x ) {
        $logger->trace( "Variable: $variable" );
    }
    $end = Time::HiRes::gettimeofday();
    $logger->info( 'Ran in ' . sprintf('%.6f', $end - $start) . ' seconds.' );

    $logger->info('Testing variable with sub{} hack...');
    $start = Time::HiRes::gettimeofday();
    for ( my $x = 0; $x < $iterations; ++$x ) {
        $logger->trace( sub{ "Variable: $variable" } );
    }
    $end = Time::HiRes::gettimeofday();
    $logger->info( 'Ran in ' . sprintf('%.6f', $end - $start) . ' seconds.' );
}

sub test_dumper()
{
    my $somewhat_complex_hashref = {
        kardashians => [
            'kim',
            'kourtney',
            'khloe',
            'kendall',
            'kylie',
        ],
        'two_plus_two' => 4,
        'foo' => {
            'bar' => {
                'baz' => {
                    'a' => {
                        'b' => [
                            'c'
                        ]
                    }
                }
            }
        }
    };

    Readonly my $iterations => 100_000;

    my ( $start, $end );

    $logger->info('Testing Dumper() without sub{} hack...');
    $start = Time::HiRes::gettimeofday();
    for ( my $x = 0; $x < $iterations; ++$x ) {
        $logger->trace( 'Somewhat complex hash: ' . Dumper( $somewhat_complex_hashref ) );
    }
    $end = Time::HiRes::gettimeofday();
    $logger->info( 'Ran in ' . sprintf('%.6f', $end - $start) . ' seconds.' );

    $logger->info('Testing Dumper() with sub{} hack...');
    $start = Time::HiRes::gettimeofday();
    for ( my $x = 0; $x < $iterations; ++$x ) {
        $logger->trace( sub{ 'Somewhat complex hash: ' . Dumper( $somewhat_complex_hashref ) } );
    }
    $end = Time::HiRes::gettimeofday();
    $logger->info( 'Ran in ' . sprintf('%.6f', $end - $start) . ' seconds.' );
}

sub main()
{
    test_variable();
    test_dumper();
}

main();