Massive installation slowdown between blead and 5.37.3 #20324

briang · 2022-09-20T08:10:46Z

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

The text was updated successfully, but these errors were encountered:

briang · 2022-09-20T08:22:37Z

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 · 2022-09-20T09:00:11Z

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 · 2022-09-20T09:38:27Z

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 · 2022-09-20T09:52:34Z

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 · 2022-09-20T09:59:17Z

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 · 2022-09-20T10:14:58Z

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 · 2022-09-20T10:15:24Z

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 · 2022-09-20T12:04:56Z

@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 · 2022-09-20T14:34:14Z

@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.

Adding more unit tests to existing test files.
Modifying existing unit tests in ways that take longer to run.
Adding more test files.
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 · 2022-09-21T08:37:10Z

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 · 2022-09-21T09:09:31Z

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 · 2022-09-21T11:31:44Z

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 · 2022-09-26T08:06:34Z

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

briang added the Needs Triage label Sep 20, 2022

briang closed this as completed Sep 21, 2022

briang mentioned this issue Oct 11, 2022

make perlbrew install bleaduse test_harness gugod/App-perlbrew#762

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Massive installation slowdown between blead and 5.37.3 #20324

Massive installation slowdown between blead and 5.37.3 #20324

briang commented Sep 20, 2022

briang commented Sep 20, 2022

demerphq commented Sep 20, 2022 via email

briang commented Sep 20, 2022

demerphq commented Sep 20, 2022 via email

demerphq commented Sep 20, 2022 via email

Leont commented Sep 20, 2022

briang commented Sep 20, 2022

briang commented Sep 20, 2022

jkeenan commented Sep 20, 2022 •

edited

Loading

briang commented Sep 21, 2022

demerphq commented Sep 21, 2022 via email

briang commented Sep 21, 2022

briang commented Sep 26, 2022

Massive installation slowdown between blead and 5.37.3 #20324

Massive installation slowdown between blead and 5.37.3 #20324

Comments

briang commented Sep 20, 2022

[Please do not change anything below this line]

Flags: category=install severity=low

briang commented Sep 20, 2022

demerphq commented Sep 20, 2022 via email

briang commented Sep 20, 2022

demerphq commented Sep 20, 2022 via email

demerphq commented Sep 20, 2022 via email

Leont commented Sep 20, 2022

briang commented Sep 20, 2022

briang commented Sep 20, 2022

jkeenan commented Sep 20, 2022 • edited Loading

briang commented Sep 21, 2022

demerphq commented Sep 21, 2022 via email

briang commented Sep 21, 2022

briang commented Sep 26, 2022

Flags:
category=install
severity=low

jkeenan commented Sep 20, 2022 •

edited

Loading