Perl performance difference between Linux distributions

[Markus Kuhn]

--------------------------------------------------------------------------
#!/usr/bin/perl
# This script takes on comparable hardware (stour, mole)
# 50 ms under openSUSE 10.2
# 4200 ms under Fedora 7

use overload q(cmp) => \&cmp;

my %h;
for (my $i=0; $i<5000; $i++) {
$h{$i} = bless [ undef, undef, { }, undef, { } ] => 'main';
}
--------------------------------------------------------------------------

Any idea, how the choice of Linux distribution on identical hardware
can affect the performance of a Perl script so dramatically
(more than an order of magnitude slower under Fedora 7)?

Fedora 7: ssh stour time ./stour-test.pl

real 0m4.308s
user 0m4.286s
sys 0m0.019s

SUSE 10.2: ssh mole time ./stour-test.pl

real 0m0.063s
user 0m0.052s
sys 0m0.012s


(The above script doesn't do anything useful, but is the result of
an attempt to prune away all for this demonstration of this effect
irrelevant parts of a much larger application.)

Any ideas for explanations or independent verifications
of the effect welcome!

Markus

 

[Mumia W.]

--------------------------------------------------------------------------
#!/usr/bin/perl
# This script takes on comparable hardware (stour, mole)
# 50 ms under openSUSE 10.2
# 4200 ms under Fedora 7

use overload q(cmp) => \&cmp;

my %h;
for (my $i=0; $i<5000; $i++) {
$h{$i} = bless [ undef, undef, { }, undef, { } ] => 'main';
}
--------------------------------------------------------------------------

Any idea, how the choice of Linux distribution on identical hardware
can affect the performance of a Perl script so dramatically
(more than an order of magnitude slower under Fedora 7)?

Fedora 7: ssh stour time ./stour-test.pl

real 0m4.308s
user 0m4.286s
sys 0m0.019s

SUSE 10.2: ssh mole time ./stour-test.pl

real 0m0.063s
user 0m0.052s
sys 0m0.012s


(The above script doesn't do anything useful, but is the result of
an attempt to prune away all for this demonstration of this effect
irrelevant parts of a much larger application.)

Any ideas for explanations or independent verifications
of the effect welcome!

Markus

How was Perl compiled on those machines?

Show us the output of "perl -V"

 

[Ilya Zakharevich]

[A complimentary Cc of this posting was sent to
Markus Kuhn

--------------------------------------------------------------------------
#!/usr/bin/perl
# This script takes on comparable hardware (stour, mole)
# 50 ms under openSUSE 10.2
# 4200 ms under Fedora 7

use overload q(cmp) => \&cmp;

my %h;
for (my $i=0; $i<5000; $i++) {
$h{$i} = bless [ undef, undef, { }, undef, { } ] => 'main';
}
--------------------------------------------------------------------------

Any idea, how the choice of Linux distribution on identical hardware
can affect the performance of a Perl script so dramatically
(more than an order of magnitude slower under Fedora 7)?

Fedora 7: ssh stour time ./stour-test.pl

real 0m4.308s
user 0m4.286s
sys 0m0.019s

SUSE 10.2: ssh mole time ./stour-test.pl

real 0m0.063s
user 0m0.052s
sys 0m0.012s

Impossible to tell until you redo with 5000 changed to 5, and with an
empty Perl command. It could be that overload.pm sits on a very slow
drive (networked behind a slow connection).

truss with timestamps...

Hope this helps,
Ilya

 

[Markus Kuhn]

|> On 08/15/07 14:05, Markus Kuhn wrote:
|> > --------------------------------------------------------------------------
|> > #!/usr/bin/perl
|> > # This script takes on comparable hardware (stour, mole)
|> > # 50 ms under openSUSE 10.2
|> > # 4200 ms under Fedora 7
|> >
|> > use overload q(cmp) => \&cmp;
|> >
|> > my %h;
|> > for (my $i=0; $i<5000; $i++) {
|> > $h{$i} = bless [ undef, undef, { }, undef, { } ] => 'main';
|> > }
|> > --------------------------------------------------------------------------
|> >
|> > Any idea, how the choice of Linux distribution on identical hardware
|> > can affect the performance of a Perl script so dramatically
|> > (more than an order of magnitude slower under Fedora 7)?
|> >
|> > Fedora 7: ssh stour time ./stour-test.pl
|> >
|> > real 0m4.308s
|> > user 0m4.286s
|> > sys 0m0.019s
|> >
|> > SUSE 10.2: ssh mole time ./stour-test.pl
|> >
|> > real 0m0.063s
|> > user 0m0.052s
|> > sys 0m0.012s
|> >
|> >
|> > (The above script doesn't do anything useful, but is the result of
|> > an attempt to prune away all for this demonstration of this effect
|> > irrelevant parts of a much larger application.)
|>
|> How was Perl compiled on those machines?
|>
|> Show us the output of "perl -V"

On both machines I used the standard Perl binaries that came with the
distributions:

Fedora 7:

Summary of my perl5 (revision 5 version 8 subversion 8) configuration:
Platform:
osname=linux, osvers=2.6.19-1.2895.fc6xen, archname=i386-linux-thread-multi
uname='linux xenbuilder1.fedora.redhat.com 2.6.19-1.2895.fc6xen #1 smp wed jan 10 19:09:13 est 2007 i686 athlon i386 gnulinux '
config_args='-des -Doptimize=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables -Dversion=5.8.8 -Dmyhostname=localhost -Dperladmin=root@localhost -Dcc=gcc -Dcf_by=Red Hat, Inc. -Dinstallprefix=/usr -Dprefix=/usr -Darchname=i386-linux -Dvendorprefix=/usr -Dsiteprefix=/usr -Duseshrplib -Dusethreads -Duseithreads -Duselargefiles -Dd_dosuid -Dd_semctl_semun -Di_db -Ui_ndbm -Di_gdbm -Di_shadow -Di_syslog -Dman3ext=3pm -Duseperlio -Dinstallusrbinperl=n -Ubincompat5005 -Uversiononly -Dpager=/usr/bin/less -isr -Dd_gethostent_r_proto -Ud_endhostent_r_proto -Ud_sethostent_r_proto -Ud_endprotoent_r_proto -Ud_setprotoent_r_proto -Ud_endservent_r_proto -Ud_setservent_r_proto -Dinc_version_list=5.8.7 5.8.6 5.8.5 -Dscriptdir=/usr/bin'
hint=recommended, useposix=true, d_sigaction=define
usethreads=define use5005threads=undef 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='gcc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -Wdeclaration-after-statement -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -I/usr/include/gdbm',
optimize='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables',
cppflags='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -Wdeclaration-after-statement -I/usr/local/include -I/usr/include/gdbm'
ccversion='', gccversion='4.1.2 20070502 (Red Hat 4.1.2-12)', 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='gcc', ldflags =' -L/usr/local/lib'
libpth=/usr/local/lib /lib /usr/lib
libs=-lresolv -lnsl -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -lc
perllibs=-lresolv -lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
libc=/lib/libc-2.6.so, so=so, useshrplib=true, libperl=libperl.so
gnulibc_version='2.6'
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E -Wl,-rpath,/usr/lib/perl5/5.8.8/i386-linux-thread-multi/CORE'
cccdlflags='-fPIC', lddlflags='-shared -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables -L/usr/local/lib'


Characteristics of this binary (from libperl):
Compile-time options: MULTIPLICITY PERL_IMPLICIT_CONTEXT
PERL_MALLOC_WRAP USE_ITHREADS USE_LARGE_FILES
USE_PERLIO USE_REENTRANT_API
Built under linux
Compiled at May 16 2007 23:23:14
@INC:
/usr/lib/perl5/site_perl/5.8.8/i386-linux-thread-multi
/usr/lib/perl5/site_perl/5.8.7/i386-linux-thread-multi
/usr/lib/perl5/site_perl/5.8.6/i386-linux-thread-multi
/usr/lib/perl5/site_perl/5.8.5/i386-linux-thread-multi
/usr/lib/perl5/site_perl/5.8.8
/usr/lib/perl5/site_perl/5.8.7
/usr/lib/perl5/site_perl/5.8.6
/usr/lib/perl5/site_perl/5.8.5
/usr/lib/perl5/site_perl
/usr/lib/perl5/vendor_perl/5.8.8/i386-linux-thread-multi
/usr/lib/perl5/vendor_perl/5.8.7/i386-linux-thread-multi
/usr/lib/perl5/vendor_perl/5.8.6/i386-linux-thread-multi
/usr/lib/perl5/vendor_perl/5.8.5/i386-linux-thread-multi
/usr/lib/perl5/vendor_perl/5.8.8
/usr/lib/perl5/vendor_perl/5.8.7
/usr/lib/perl5/vendor_perl/5.8.6
/usr/lib/perl5/vendor_perl/5.8.5
/usr/lib/perl5/vendor_perl
/usr/lib/perl5/5.8.8/i386-linux-thread-multi
/usr/lib/perl5/5.8.8

 

[Markus Kuhn]

|> Impossible to tell until you redo with 5000 changed to 5, and with an
|> empty Perl command. It could be that overload.pm sits on a very slow
|> drive (networked behind a slow connection).

In both cases, all files loaded came from block-buffer cache,
because I have repeated the test runs until the test times
were stable, to elimate I/O latency affecting the runtimes.

The time difference happens entirely within the for loop iterations.
During this time, the only system call that is shown in strace
are 13 consecutive calls to brk to allocate more memory, and the
time difference is entirely in user time, not in system time.

Most minor changes to this program (which -- as I mentioned
-- is already the outcome of a lengthy attempt to strip down with
the help of DProf all irrelevant parts from a huge application
that first exhibited this off problem) cause the dramatic
run-time difference to disappear. Such changes include
for example blessing to another class than "main" or removing
the cmp overload.

My speculation is that something odd is going wrong with how
Perl has been compiled under Fedora 7, threading libraries or
whatever.

Markus

 

[Markus Kuhn]

(e-mail address removed) (Alan Curry) writes:
|> In article <[email protected]>,
|> >Fedora 7: ssh stour time ./stour-test.pl
|> >
|> >real 0m4.308s
|> >user 0m4.286s
|> >sys 0m0.019s
|>
|> This looks like a good case for perl -dProf and dprofpp.

The example program is already the result or stripping away
from my larger application that first showed this problem every
irrelevant part. Since there are no longer any user-defined
subroutines involved, the output of dprofpp is no longer
meaningful. I suspect that the combination of the bless and the
overload is triggering this, because removing either fixes the
problem.

Markus

 

[xhoster]

-------------------------------------------------------------------------
- #!/usr/bin/perl
# This script takes on comparable hardware (stour, mole)
# 50 ms under openSUSE 10.2
# 4200 ms under Fedora 7

use overload q(cmp) => \&cmp;

my %h;
for (my $i=0; $i<5000; $i++) {
$h{$i} = bless [ undef, undef, { }, undef, { } ] => 'main';
}
-------------------------------------------------------------------------

What happens if you change it to:

use overload q(cmp) => sub { warn "calling cmp with @_" };

Since you don't define a sub named cmp, I would expect it to die
if somehow the overload was taking effect, but it would be nice to
see explicit confirmation of that.

Xho

 

[xhoster]

|> >
|> > (The above script doesn't do anything useful, but is the result of
|> > an attempt to prune away all for this demonstration of this effect
|> > irrelevant parts of a much larger application.)
|>
|> How was Perl compiled on those machines?
|>
|> Show us the output of "perl -V"

On both machines I used the standard Perl binaries that came with the
distributions:

What if you compile your own perl on each machine from the same source
code? Maybe the vendor distributions have done something strange to their
code. At least if you could reproduce the issue with the default
compilation of a standard source-code distribution, it would give others
interested in exploring the issue a good starting point.

Xho

 

[Ilya Zakharevich]

[A complimentary Cc of this posting was sent to
Markus Kuhn

Most minor changes to this program (which -- as I mentioned
-- is already the outcome of a lengthy attempt to strip down with
the help of DProf all irrelevant parts from a huge application
that first exhibited this off problem) cause the dramatic
run-time difference to disappear. Such changes include
for example blessing to another class than "main" or removing
the cmp overload.

My speculation is that something odd is going wrong with how
Perl has been compiled under Fedora 7, threading libraries or
whatever.

Fedora Perl is DEBUGGING, which is a NONONO. But I do not think this
would explain 100x slowdown; usually I would expect something like
3x..4x slowdown...

Hope this helps,
Ilya

 

[Markus Kuhn]

|> > My speculation is that something odd is going wrong with how
|> > Perl has been compiled under Fedora 7, threading libraries or
|> > whatever.
|>
|> Fedora Perl is DEBUGGING, which is a NONONO. But I do not think this
|> would explain 100x slowdown; usually I would expect something like
|> 3x..4x slowdown...

It is actually the other way round: SUSE 10.2's Perl
(where the test runs much faster) was compiled with DEBUGGING,
whereas Fedora 7 Perl was not.

Markus

 

[Markus Kuhn]

I have now filed a bug report on this issue at

https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=253728

Markus