Stories
Slash Boxes
Comments
NOTE: use Perl; is on undef hiatus. You can read content, but you can't post it. More info will be forthcoming forthcomingly.

All the Perl that's Practical to Extract and Report

use Perl Log In

Log In

[ Create a new account ]

perigrin (3495)

perigrin
  chrisNO@SPAMprather.org
http://chris.prather.org/
AOL IM: marceusx (Add Buddy, Send Message)

After Middle School Chris bounced through various high schools around the state of Florida for a bit. He ended up getting a BA (in English) from the University of Central Florida at about the time others his age were getting their MAs. His (now) wife, their child, and he went to Europe for a bit (there was a programming job in Scotland) and came back unemployed where upon he got offered a job in St. Paul. He moved on from that job after a few years to one where he was paid to do the things he previously did as a hobby. That sounds much more exciting than it really was. Really his life is based on two kids, two cats, and a bunny.

Journal of perigrin (3495)

Thursday September 07, 2006
02:53 PM

Perl 5.8 slowness ...

[ #30919 ]

So at work we are going through and updating our toolset. This included moving from Perl 5.6.1 to 5.8.8 (Yay!). However we discovered a deal breaking issue. Perl 5.8.8 is much slower than 5.6.1. We discovered a slowdown of around 100% between 5.6.1 and 5.8.8 using as close to default installs as we could. (Things that used to take 30 seconds were now taking a minute, and we have some time critical production code.) After doing some inspection I found the largest cause to the slowdown was the change in 5.8.0 to use the system malloc instead of perl’s internal malloc (-Dusemymalloc) by default on Solaris. Fixing this we went back to a roughly 20% slowdown. I never found a clear explanation of why they switched the default malloc other than a reference to corruption and segfaulting when dealing with over 2G of memory (was that RAM or LARGEFILE support?) … does anybody have a pointer?

I’ve been trying to track this down for a couple weeks, and I’ve discovered that this slowdown is true on every platform I’ve tested it on (Solaris, Darwin, Linux). I also found a reference to it on P5P from several years ago that appears to be warnocked. I’m stumped as to what else to try. Below are the benchmarks from my Linux machine along with the benchmark script.

Note that this may look like I’m arguing over peanuts with the tests running in less than 10 seconds. Multiply everything by 4 to roughly get the speeds on our Solaris boxes at work.

perigrin@schroedinger ~/dev/perl_speed/rdsmerge $ perl5.9.4 split_test.pl
do_split:        4 wallclock secs ( 3.59 usr +  0.00 sys =  3.59 CPU) @ 69637.88/s (n=250000)
do_split_loop:   8 wallclock secs ( 7.38 usr +  0.01 sys =  7.39 CPU) @ 33829.50/s (n=250000)
do_split_loop_ia:        7 wallclock secs ( 6.65 usr +  0.00 sys =  6.65 CPU) @  0.15/s (n=1)

perigrin@schroedinger ~/dev/perl_speed/rdsmerge $ perl5.8.8 split_test.pl
do_split:        5 wallclock secs ( 3.99 usr +  0.00 sys =  3.99 CPU) @ 62656.64/s (n=250000)
do_split_loop:   9 wallclock secs ( 8.55 usr +  0.00 sys =  8.55 CPU) @ 29239.77/s (n=250000)
do_split_loop_ia:        7 wallclock secs ( 7.55 usr +  0.01 sys =  7.56 CPU) @  0.13/s (n=1)

# -Dusemymalloc
perigrin@schroedinger ~/dev/perl_speed/rdsmerge $ perl5.8.8+ split_test.pl
do_split:        3 wallclock secs ( 2.82 usr +  0.00 sys =  2.82 CPU) @ 88652.48/s (n=250000)
do_split_loop:   6 wallclock secs ( 5.84 usr +  0.01 sys =  5.85 CPU) @ 42735.04/s (n=250000)
do_split_loop_ia:        6 wallclock secs ( 5.55 usr +  0.01 sys =  5.56 CPU) @  0.18/s (n=1)

# -Dusemymalloc
perigrin@schroedinger /home/projects/perl_speed/rdsmerge $ perl5.8.5  split_test.pl
do_split:        3 wallclock secs ( 2.75 usr +  0.00 sys =  2.75 CPU) @ 90909.09/s (n=250000)
do_split_loop:   5 wallclock secs ( 6.07 usr +  0.00 sys =  6.07 CPU) @ 41186.16/s (n=250000)
do_split_loop_ia:        6 wallclock secs ( 5.52 usr +  0.00 sys =  5.52 CPU) @  0.18/s (n=1)

# -Uusemymalloc aka System Malloc
perigrin@schroedinger /home/projects/perl_speed/rdsmerge $ perl5.8.5- split_test.pl
do_split:        4 wallclock secs ( 3.50 usr +  0.00 sys =  3.50 CPU) @ 71428.57/s (n=250000)
do_split_loop:   8 wallclock secs ( 7.30 usr +  0.01 sys =  7.31 CPU) @ 34199.73/s (n=250000)
do_split_loop_ia:        6 wallclock secs ( 6.28 usr +  0.00 sys =  6.28 CPU) @  0.16/s (n=1)

perigrin@schroedinger ~/dev/perl_speed/rdsmerge $ perl5.6.2 split_test.pl
do_split:        3 wallclock secs ( 2.57 usr +  0.00 sys =  2.57 CPU) @ 97276.26/s (n=250000)
do_split_loop:   6 wallclock secs ( 6.27 usr +  0.00 sys =  6.27 CPU) @ 39872.41/s (n=250000)
do_split_loop_ia:        6 wallclock secs ( 5.63 usr +  0.01 sys =  5.64 CPU) @  0.18/s (n=1)

# -Dusemymalloc
perigrin@schroedinger ~/dev/perl_speed/rdsmerge $ perl5.6.2+ split_test.pl
do_split:        1 wallclock secs ( 2.22 usr +  0.00 sys =  2.22 CPU) @ 112612.61/s (n=250000)
do_split_loop:   6 wallclock secs ( 5.69 usr +  0.00 sys =  5.69 CPU) @ 43936.73/s (n=250000)
do_split_loop_ia:        5 wallclock secs ( 5.20 usr +  0.00 sys =  5.20 CPU) @  0.19/s (n=1)

--- split_test.pl ---

#!/usr/local/bin/perl5

use Benchmark;
use strict;
use warnings;

my $r = timeit( 250000, sub { do_split(); } );
my $r2 = timeit( 250000, sub { do_split_loop(); } );
#my $r2 = timeit( 250000, sub { do_split_noregex(); } );
#my $r3 = timeit( 250000, sub { do_split_bytes(); } );
my $r3 = timeit( 1, sub { do_split_loop_ia(); } );

print "do_split:\t", timestr($r), "\n";
print "do_split_loop:\t", timestr($r2), "\n";
print "do_split_loop_ia:\t", timestr($r3), "\n";

exit;

sub do_split
{
    my $input = "0|hucalc8|hucalc8a0|00:00:04|2|0x00000b0000339fa7|3620316P6|E|P|0.125000|PRICE| BID|3620316P6|GNPL   006278  8.500 07/15/18|100.469000|8.446256|8.446256|5.398844|20060808|20060823|";

    my @fields = split /\|/, $input;
    my $f1 = $fields[1];
    my $f2 = $fields[1];

    return;
}

sub do_split_loop
{
    my $input = "0|hucalc8|hucalc8a0|00:00:04|2|0x00000b0000339fa7|3620316P6|E|P|0.125000|PRICE| BID|3620316P6|GNPL   006278  8.500 07/15/18|100.469000|8.446256|8.446256|5.398844|20060808|20060823|";

    my @fields = split /\|/, $input;
    my $f1 = $fields[1];
    my $f2 = $fields[1];
    my $foo;
    my @out;

    ## loop 15 building array by force
    for ( my $i = 0; $i < 15; $i++ ) {
        if (defined $fields[$i]) {
            $out[$i] = $fields[$i];
        }
    }

    return;
}

sub do_split_loop_ia
{
    my $count = 250000;
    my $input = "0|hucalc8|hucalc8a0|00:00:04|2|0x00000b0000339fa7|3620316P6|E|P|0.125000|PRICE| BID|3620316P6|GNPL   006278  8.500 07/15/18|100.469000|8.446256|8.446256|5.398844|20060808|20060823|";

    my @out;
    my $foo;

    foreach (0..$count) {
        my @fields = split /\|/, $input;

        ## loop 15 building array by force
        for ( my $i = 0; $i < 15; $i++ ) {
            if (defined $fields[$i]) {
                $out[$i] = $fields[$i];
            }
        }

        $foo = join( ',', @out );
    }

    return;
}

The Fine Print: The following comments are owned by whoever posted them. We are not responsible for them in any way.
 Full
 Abbreviated
 Hidden
More | Login | Reply
Loading... please wait.