Massive installation slowdown between blead and 5.37.3

[briang]

This is a bug report for perl from briang@cpan.org,
generated with the help of perlbug 1.42 running under perl 5.36.0.

---

[Please describe your issue here]

Installing perls <= 5.37.3 usually takes 3-5 minutes depending on configure
options. Blead (as of 2022-09-20 08:50 BST) takes 11-15 minutes.

Here's an example of installing blead

$ time perlbrew install perl-blead --noman -j 5
Fetching perl-blead as /opt/perl/dists/blead.tar.gz
Installing /opt/perl/build/blead/perl5-blead into /opt/perl/perls/perl-blead

This could take a while. You can run the following command on another shell to track the status:

  tail -f /opt/perl/build.perl-blead.log

perl-blead is successfully installed.

real	11m35.718s
user	8m31.758s
sys	0m51.623s

and installing 5.37.3

$ time perlbrew install perl-5.37.3 --noman -j 5
Fetching perl 5.37.3 as /opt/perl/dists/perl-5.37.3.tar.gz
Download https://cpan.metacpan.org/src/5.0/perl-5.37.3.tar.gz to /opt/perl/dists/perl-5.37.3.tar.gz
Installing /opt/perl/build/perl-5.37.3/perl-5.37.3 into /opt/perl/perls/perl-5.37.3

This could take a while. You can run the following command on another shell to track the status:

  tail -f /opt/perl/build.perl-5.37.3.log

perl-5.37.3 is successfully installed.

real	3m41.997s
user	8m42.773s
sys	0m48.984s

I've tried with gcc (Ubuntu 11.2.0-19ubuntu1) 11.2.0 and Ubuntu clang version
14.0.0-1ubuntu1 and there's no significant difference.

I'm using a VirtualBox (v6.1.38) VM with 4 Ryzen 3700X CPU cores @ 3.6 GHz and
4GB RAM. OS is Ubuntu 22.04.

[Please do not change anything below this line]

---

Flags:
category=install
severity=low

Site configuration information for perl 5.36.0:

Configured by brian at Thu Sep 15 09:39:10 BST 2022.

Summary of my perl5 (revision 5 version 36 subversion 0) configuration:

Platform:
osname=linux
osvers=5.15.0-47-generic
archname=x86_64-linux-thread-multi-ld
uname='linux dev 5.15.0-47-generic #51-ubuntu smp thu aug 11 07:51:15 utc 2022 x86_64 x86_64 x86_64 gnulinux '
config_args='-de -Dprefix=/opt/perl/perls/perl-5.36.0 -Dusethreads -Duselongdouble -Aeval:scriptdir=/opt/perl/perls/perl-5.36.0/bin'
hint=recommended
useposix=true
d_sigaction=define
useithreads=define
usemultiplicity=define
use64bitint=define
use64bitall=define
uselongdouble=define
usemymalloc=n
default_inc_excludes_dot=define
Compiler:
cc='cc'
ccflags ='-D_REENTRANT -D_GNU_SOURCE -fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64'
optimize='-O2'
cppflags='-D_REENTRANT -D_GNU_SOURCE -fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
ccversion=''
gccversion='11.2.0'
gccosandvers=''
intsize=4
longsize=8
ptrsize=8
doublesize=8
byteorder=12345678
doublekind=3
d_longlong=define
longlongsize=8
d_longdbl=define
longdblsize=16
longdblkind=3
ivtype='long'
ivsize=8
nvtype='long double'
nvsize=16
Off_t='off_t'
lseeksize=8
alignbytes=16
prototype=define
Linker and Libraries:
ld='cc'
ldflags =' -fstack-protector-strong -L/usr/local/lib'
libpth=/usr/local/lib /usr/lib/x86_64-linux-gnu /usr/lib /usr/lib64
libs=-lpthread -lnsl -lgdbm -ldb -ldl -lm -lcrypt -lutil -lc -lgdbm_compat
perllibs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
libc=/lib/x86_64-linux-gnu/libc.so.6
so=so
useshrplib=false
libperl=libperl.a
gnulibc_version='2.35'
Dynamic Linking:
dlsrc=dl_dlopen.xs
dlext=so
d_dlsymun=undef
ccdlflags='-Wl,-E'
cccdlflags='-fPIC'
lddlflags='-shared -O2 -L/usr/local/lib -fstack-protector-strong'

---

@inc for perl 5.36.0:
/opt/perl/perls/perl-5.36.0/lib/site_perl/5.36.0/x86_64-linux-thread-multi-ld
/opt/perl/perls/perl-5.36.0/lib/site_perl/5.36.0
/opt/perl/perls/perl-5.36.0/lib/5.36.0/x86_64-linux-thread-multi-ld
/opt/perl/perls/perl-5.36.0/lib/5.36.0

---

Environment for perl 5.36.0:
HOME=/home/brian
LANG=en_GB.UTF-8
LANGUAGE=en_GB:en
LD_LIBRARY_PATH (unset)
LOGDIR (unset)
PATH=/opt/perl/bin:/opt/perl/perls/perl-5.36.0/bin:/home/nix/bin:/home/brian/.nix-profile/bin:/home/brian/bin:/home/brian/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/bin
PERLBREW=command perlbrew
PERLBREW_HOME=/home/brian/.perlbrew
PERLBREW_MANPATH=/opt/perl/perls/perl-5.36.0/man
PERLBREW_PATH=/opt/perl/bin:/opt/perl/perls/perl-5.36.0/bin
PERLBREW_PERL=perl-5.36.0
PERLBREW_ROOT=/opt/perl
PERLBREW_SHELLRC_VERSION=0.96
PERLBREW_VERSION=0.96
PERL_BADLANG (unset)
SHELL=/bin/bash

[briang]

It's the tests:

$ time perlbrew install perl-5.37.3 --notest --noman -j 5
...
real	1m11.317s
user	2m31.086s
sys	0m13.604s

$ time perlbrew install perl-blead --notest --noman -j 5
...
real	1m16.142s
user	2m33.745s
sys	0m13.611s

[demerphq]

On Tue, 20 Sept 2022, 09:22 brian greenfield, ***@***.***> wrote: It's the tests: $ time perlbrew install perl-5.37.3 --notest --noman -j 5 ... real 1m11.317s user 2m31.086s sys 0m13.604s $ time perlbrew install perl-blead --notest --noman -j 5 ... real 1m16.142s user 2m33.745s sys 0m13.611s

Try exporting TEST_JOBS=4 replace 4 with whatever you are feeding to -j. Telling the maker to use K processes doesn't translate into the tests using K processes and some of the newer tests take a while so running them in parallel makes a big difference. Yves

…

[briang]

It didn't make a significant difference:

$ export TEST_JOBS=5
$ time make test
...
Elapsed: 620 sec
u=7.16  s=9.61  cu=346.54  cs=27.48  scripts=2505  tests=1175939

real	10m25.567s
user	5m58.762s
sys	0m37.697s

[demerphq]

On Tue, 20 Sept 2022, 10:38 brian greenfield, ***@***.***> wrote: It didn't make a significant difference: $ export TEST_JOBS=5 $ time make test ... Elapsed: 620 sec u=7.16 s=9.61 cu=346.54 cs=27.48 scripts=2505 tests=1175939 real 10m25.567s user 5m58.762s sys 0m37.697s — Reply to this email directly, view it on GitHub <#20324 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAZ5R7PP4434DNNNCJ6UKLV7GAZ5ANCNFSM6AAAAAAQQZ427I> . You are receiving this because you commented.

You need to use test_harness and don't remove the -j argument to make. TEST_JOBS=5 make -j5 test_harness

…

Message ID: ***@***.***>

[demerphq]

On Tue, 20 Sept 2022, 10:52 demerphq, ***@***.***> wrote: On Tue, 20 Sept 2022, 10:38 brian greenfield, ***@***.***> wrote: > It didn't make a significant difference: > > $ export TEST_JOBS=5 > $ time make test > ... > Elapsed: 620 sec > u=7.16 s=9.61 cu=346.54 cs=27.48 scripts=2505 tests=1175939 > > real 10m25.567s > user 5m58.762s > sys 0m37.697s > > — > Reply to this email directly, view it on GitHub > <#20324 (comment)>, or > unsubscribe > <https://github.com/notifications/unsubscribe-auth/AAAZ5R7PP4434DNNNCJ6UKLV7GAZ5ANCNFSM6AAAAAAQQZ427I> > . > You are receiving this because you commented. > You need to use test_harness and don't remove the -j argument to make. TEST_JOBS=5 make -j5 test_harness

Sorry, fat fingered send too early. Perl has two test targets in its Makefile and only one of them supports parallel tests. The default (for most platforms) does not support it. Not sure why frankly, but there you go. Yves

…

Message ID: ***@***.***> >

[Leont]

If you run tests with HARNESS_TIMER=1 you will get run times for individual tests (not sure it combines well with parallelization). You can use that figure out where the difference comes from.

[briang]

Grrr. I did have a look at perlhack.pod, but stopped at

TEST_JOBS=3 make test_harness  # Run 3 tests in parallel

I should have read on where it explains about -j😠

With TEST_JOBS=5 and -j 5:

Elapsed: 565 sec
u=7.11  s=11.94  cu=290.50  cs=24.74  scripts=2454  tests=1218730

real	9m27.530s
user	5m2.814s
sys	0m37.441s

A bit faster than it was but still a lot slower than 5.37.3.

[briang]

@Leont

I ran the blead and 5.37.3 test suites with HARNESS_TIMER=1 and compared the results of all the tests that took 1 second or more. (Luckily, I know a programming language that helped with that😊) The only significant difference I found was cpan/Memoize/t/speed that took 3 seconds longer on blead

[jkeenan]

@Leont

I ran the blead and 5.37.3 test suites with HARNESS_TIMER=1 and compared the results of all the tests that took 1 second or more. (Luckily, I know a programming language that helped with thatblush) The only significant difference I found was cpan/Memoize/t/speed that took 3 seconds longer on blead

There are four possible sources of slowdowns in the running time of the test suite.

1. Adding more unit tests to existing test files.
2. Modifying existing unit tests in ways that take longer to run.
3. Adding more test files.
4. Slowdown in the perl executable.

Only number 4 is cause for serious concern, IMO.

Between v5.37.3 and HEAD of blead (v5.37.3-326-gf1cc674150) we added 5 new test files and removed 1. I don't know how many unit tests were added or whether the running time of existing unit tests has changed.

In the environment in which I customarily test (FreeBSD-12; clang-10; threaded build; TEST_JOBS=4), I identified those test files whose names did not change over that period but whose contents did change. I excluded the 5 new test files and the 1 that was removed. I ran the remaining files through the test harness at the "before" and "after" builds.

At v5.37.3 I got running times around 17.7 seconds. At HEAD I got about 18.6 seconds. I did this about a half dozen times -- not enough to be truly statistically significant. And I could not distinguish between the "adding more unit tests" and "perl getting slower" possibilities.

The only way we can resolve this is with much better benchmarking than I am capable of.

[briang]

With the release of 5.37.4, I've timed that against 5.37.3 and blead. There's no real difference between .3 and .4:

$ time perlbrew install perl-5.37.3 --noman -j5
...
real 3m42.662s
user 8m41.147s
sys  0m54.661s

$ time perlbrew install perl-5.37.4 --noman -j5
...
real 3m44.629s
user 8m45.999s
sys  0m53.922s

However, blead @ 9:21 BST (8183085) is still slow:

$ time perlbrew install perl-blead --noman -j5
...
real 11m20.945s
user 8m14.818s
sys  0m48.992s

(I've used perlbrew because it uses test_harness and TEST_JOBS)

Given that the slowdown is limited to blead, I'm going to close this issue now.

Thanks for all your help

[demerphq]

On Wed, 21 Sept 2022, 09:37 brian greenfield, ***@***.***> wrote: With the release of 5.37.4, I've timed that against 5.37.3 and blead. There's no real difference between .3 and .4: $ time perlbrew install perl-5.37.3 --noman -j5 ... real 3m42.662s user 8m41.147s sys 0m54.661s $ time perlbrew install perl-5.37.4 --noman -j5 ... real 3m44.629s user 8m45.999s sys 0m53.922s However, blead @ 9:21 BST (8183085 <8183085>) is still slow: $ time perlbrew install perl-blead --noman -j5 ... real 11m20.945s user 8m14.818s sys 0m48.992s (I've used perlbrew because it uses test_harness and TEST_JOBS) Given that the slowdown is limited to blead, I'm going to close this issue now. Thanks for all your help

One question, did you check to see if blead is being built with DEBUGGING but the others are not? DEBUGGING mode massively slows down the tests. Yves

…

[briang]

Unfortunately not:

$ ../perls/perl-blead/bin/perl -V:config_args
config_args='-de -Dprefix=/home/cpan/perlbrew/perls/perl-blead -Dman1dir=none -Dman3dir=none -Dusedevel -Aeval:scriptdir=/home/cpan/perlbrew/perls/perl-blead/bin';

[briang]

For anyone still reading...

perlbrew treats blead differently to other perls. Specifically, for non-blead it runs

make -j5
make test_harness 
make install

and for blead

make -j5
make test
make install

Also, if test_harness is being used, $ENV{TEST_JOBS}=5