Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slowdown in integer loops #15975

Closed
p5pRT opened this issue May 12, 2017 · 13 comments
Closed

Slowdown in integer loops #15975

p5pRT opened this issue May 12, 2017 · 13 comments

Comments

@p5pRT
Copy link

p5pRT commented May 12, 2017

Migrated from rt.perl.org#131291 (status was 'rejected')

Searchable as RT131291$

@p5pRT
Copy link
Author

p5pRT commented May 12, 2017

From sschoeling@linet-services.de

Created by sschoeling@linet-services.de

The following snippet loses about 20% speed between 5.25.9 and 5.26.0RC1

  use integer;
  for my $n (1..2e5) {
  my $k = 0;
  while (1) {
  last unless 0 < ($n -= 3*++$k - 2);
  }
  }

5.25.9​: 3.120s
5.26.0​: 3.745s

For some reason the slowdown is less without use integer​:

5.25.9​: 3.200s
5.26.0​: 3.387s

Bisect on the same repo and config.sh as this perlbug says​:

  commit f49e846
  Author​: David Mitchell <davem@​iabyn.com>
  Date​: Mon Feb 27 13​:15​:31 2017 +0000

  S_do_op_dump_bar()​: don't print TRANS op_pv field

  My recent commit v5.25.9-32-gabd07ec made dump.c display the op_pv
  string of OP_NEXT, OP_TRANS etc ops. However, for OP_TRANS/OP_TRANSR,
  the string is basically a 256-byte potentially non null-temrinated array.
  This was causing a buffer read overrun and garbage to be displayed.

  The simple solution is to only display the address but not contents
  for a trans op. OP_NEXT ec labels continue to be displayed.

Perl Info

Flags:
    category=core
    severity=low

Site configuration information for perl 5.26.0:

Configured by sschoeling at Fri May 12 11:10:07 CEST 2017.

Summary of my perl5 (revision 5 version 26 subversion 0) configuration:
  Commit id: b97ea83254457bb54ffb80694b355111d431712c
  Platform:
    osname=linux
    osvers=3.13.0-115-generic
    archname=x86_64-linux
    uname='linux plum-chiew 3.13.0-115-generic #162-ubuntu smp fri mar 24 16:03:51 utc 2017 x86_64 x86_64 x86_64 gnulinux '
    config_args=''
    hint=recommended
    useposix=true
    d_sigaction=define
    useithreads=undef
    usemultiplicity=undef
    use64bitint=define
    use64bitall=define
    uselongdouble=undef
    usemymalloc=n
    default_inc_excludes_dot=define
    bincompat5005=undef
  Compiler:
    cc='cc'
    ccflags ='-fwrapv -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64'
    optimize='-O2'
    cppflags='-fwrapv -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include'
    ccversion=''
    gccversion='4.8.4'
    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='double'
    nvsize=8
    Off_t='off_t'
    lseeksize=8
    alignbytes=8
    prototype=define
  Linker and Libraries:
    ld='cc'
    ldflags =' -fstack-protector -L/usr/local/lib'
    libpth=/usr/local/lib /usr/lib/gcc/x86_64-linux-gnu/4.8/include-fixed /usr/include/x86_64-linux-gnu /usr/lib /lib/x86_64-linux-gnu /lib/../lib /usr/lib/x86_64-linux-gnu /usr/lib/../lib /lib
    libs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
    perllibs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
    libc=libc-2.19.so
    so=so
    useshrplib=false
    libperl=libperl.a
    gnulibc_version='2.19'
  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'



@INC for perl 5.26.0:
    /home/sschoeling/lib/perl5/site_perl/5.26.0/x86_64-linux
    /home/sschoeling/lib/perl5/site_perl/5.26.0
    /home/sschoeling/lib/perl5/5.26.0/x86_64-linux
    /home/sschoeling/lib/perl5/5.26.0
    /home/sschoeling/lib/perl5/site_perl


Environment for perl 5.26.0:
    HOME=/home/sschoeling
    LANG=en_US.UTF-8
    LANGUAGE=en_US
    LC_ADDRESS=de_DE.UTF-8
    LC_IDENTIFICATION=de_DE.UTF-8
    LC_MEASUREMENT=de_DE.UTF-8
    LC_MONETARY=de_DE.UTF-8
    LC_NAME=de_DE.UTF-8
    LC_NUMERIC=de_DE.UTF-8
    LC_PAPER=de_DE.UTF-8
    LC_TELEPHONE=de_DE.UTF-8
    LC_TIME=de_DE.UTF-8
    LD_LIBRARY_PATH (unset)
    LOGDIR (unset)
    PATH=/opt/sschoeling/perlbrew/bin:/home/sschoeling/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games
    PERLBREW_BASHRC_VERSION=0.66
    PERLBREW_HOME=/home/sschoeling/.perlbrew
    PERLBREW_ROOT=/opt/sschoeling/perlbrew
    PERL_BADLANG (unset)
    SHELL=/bin/bash

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @jkeenan

On Fri, 12 May 2017 12​:45​:00 GMT, sschoeling@​linet-services.de wrote​:

This is a bug report for perl from sschoeling@​linet-services.de,
generated with the help of perlbug 1.40 running under perl 5.26.0.

-----------------------------------------------------------------
[Please describe your issue here]

The following snippet loses about 20% speed between 5.25.9 and
5.26.0RC1

use integer;
for my $n (1..2e5) {
my $k = 0;
while (1) {
last unless 0 < ($n -= 3*++$k - 2);
}
}

5.25.9​: 3.120s
5.26.0​: 3.745s

For some reason the slowdown is less without use integer​:

5.25.9​: 3.200s
5.26.0​: 3.387s

Bisect on the same repo and config.sh as this perlbug says​:

commit f49e846
Author​: David Mitchell <davem@​iabyn.com>
Date​: Mon Feb 27 13​:15​:31 2017 +0000

S_do_op_dump_bar()​: don't print TRANS op_pv field

My recent commit v5.25.9-32-gabd07ec made dump.c display the op_pv
string of OP_NEXT, OP_TRANS etc ops. However, for OP_TRANS/OP_TRANSR,
the string is basically a 256-byte potentially non null-temrinated
array.
This was causing a buffer read overrun and garbage to be displayed.

The simple solution is to only display the address but not contents
for a trans op. OP_NEXT ec labels continue to be displayed.

Focusing first on the variant without 'use integer;' ...

While I get a slowdown from 5.24.1 to HEAD of blead, the slowdown is not as great as yours and I don't find evidence that the slowdown is caused (solely) by the commit you identified. Please see attachments.

Thank you very much.

--
James E Keenan (jkeenan@​cpan.org)

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @jkeenan

131291-slowdown.pl

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @jkeenan

perl-5.24.1
$ time perl 131291-slowdown.pl

real 0m2.773s
user 0m2.772s
sys 0m0.000s

$ git clean -dfx
$ git checkout v5.25.9
$ git show | head -1
commit 5d577b6
# configure and build perl
$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 25, subversion 9 (v5.25.9) built for x86_64-linux
$ time ./perl -Ilib ~/learn/perl/p5p/131291-slowdown.pl

real 0m2.790s
user 0m2.788s
sys 0m0.000s

$ git clean -dfx
$ git checkout f49e846^
# configure and build perl
$ git show | head -1
commit 41b1e85
$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 25, subversion 11 (v5.25.11 (v5.25.10-43-g41b1e85)) built for x86_64-linux
$ time ./perl -Ilib ~/learn/perl/p5p/131291-slowdown.pl

real 0m2.843s
user 0m2.800s
sys 0m0.000s

$ git clean -dfx
$ git checkout f49e846
# configure and build perl
$ git show | head -1
commit f49e846
$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 25, subversion 11 (v5.25.11 (v5.25.10-44-gf49e846)) built for x86_64-linux
$ time ./perl -Ilib ~/learn/perl/p5p/131291-slowdown.pl

real 0m2.854s
user 0m2.852s
sys 0m0.000s

$ git clean -dfx
$ git checkout blead
$ git show | head -1
commit b97ea83
# configure and build perl
$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 26, subversion 0 (v5.26.0-RC1-7-gb97ea83) built for x86_64-linux
$ time ./perl -Ilib ~/learn/perl/p5p/131291-slowdown.pl

real 0m2.817s
user 0m2.816s
sys 0m0.000s

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

The RT System itself - Status changed from 'new' to 'open'

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @jkeenan

On Sat, 13 May 2017 01​:55​:59 GMT, jkeenan wrote​:

On Fri, 12 May 2017 12​:45​:00 GMT, sschoeling@​linet-services.de wrote​:

This is a bug report for perl from sschoeling@​linet-services.de,
generated with the help of perlbug 1.40 running under perl 5.26.0.

-----------------------------------------------------------------
[Please describe your issue here]

The following snippet loses about 20% speed between 5.25.9 and
5.26.0RC1

use integer;
for my $n (1..2e5) {
my $k = 0;
while (1) {
last unless 0 < ($n -= 3*++$k - 2);
}
}

5.25.9​: 3.120s
5.26.0​: 3.745s

For some reason the slowdown is less without use integer​:

5.25.9​: 3.200s
5.26.0​: 3.387s

Bisect on the same repo and config.sh as this perlbug says​:

commit f49e846
Author​: David Mitchell <davem@​iabyn.com>
Date​: Mon Feb 27 13​:15​:31 2017 +0000

S_do_op_dump_bar()​: don't print TRANS op_pv field

My recent commit v5.25.9-32-gabd07ec made dump.c display the op_pv
string of OP_NEXT, OP_TRANS etc ops. However, for OP_TRANS/OP_TRANSR,
the string is basically a 256-byte potentially non null-temrinated
array.
This was causing a buffer read overrun and garbage to be displayed.

The simple solution is to only display the address but not contents
for a trans op. OP_NEXT ec labels continue to be displayed.

Focusing first on the variant without 'use integer;' ...

While I get a slowdown from 5.24.1 to HEAD of blead, the slowdown is
not as great as yours and I don't find evidence that the slowdown is
caused (solely) by the commit you identified. Please see attachments.

Thank you very much.

In addition, these results may be very platform-specific. Please find attached results from running the same program in a FreeBSD-10.3 VM. There was significant performance improvement between 5.20.3 and 5.24.1 and a slight (probably not significant) improvement between 5.24.1 and HEAD.

Thank you very much.
--
James E Keenan (jkeenan@​cpan.org)

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @jkeenan

# FreeBSD-10.3-RELEASE

# vendor perl
$ perl -v | head -2 | tail -1
This is perl 5, version 20, subversion 3 (v5.20.3) built for amd64-freebsd-thread-multi
$ time perl ~/learn/perl/p5p/131291-slowdown.pl
  4.68 real 4.49 user 0.07 sys

$ git checkout v5.24.1
$ perl -v | head -2 | tail -1
This is perl 5, version 24, subversion 1 (v5.24.1) built for amd64-freebsd-thread-multi
$ time ./perl -Ilib ~/learn/perl/p5p/131291-slowdown.pl
  3.18 real 3.03 user 0.06 sys

$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 26, subversion 0 (v5.26.0-RC1-7-gb97ea83) built for amd64-freebsd-thread-multi
$ time ./perl -Ilib ~/learn/perl/p5p/131291-slowdown.pl
  3.20 real 3.05 user 0.06 sys

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @jkeenan

On Sat, 13 May 2017 02​:11​:42 GMT, jkeenan wrote​:

On Sat, 13 May 2017 01​:55​:59 GMT, jkeenan wrote​:

On Fri, 12 May 2017 12​:45​:00 GMT, sschoeling@​linet-services.de wrote​:

This is a bug report for perl from sschoeling@​linet-services.de,
generated with the help of perlbug 1.40 running under perl 5.26.0.

-----------------------------------------------------------------
[Please describe your issue here]

The following snippet loses about 20% speed between 5.25.9 and
5.26.0RC1

use integer;
for my $n (1..2e5) {
my $k = 0;
while (1) {
last unless 0 < ($n -= 3*++$k - 2);
}
}

5.25.9​: 3.120s
5.26.0​: 3.745s

For some reason the slowdown is less without use integer​:

5.25.9​: 3.200s
5.26.0​: 3.387s

Bisect on the same repo and config.sh as this perlbug says​:

commit f49e846
Author​: David Mitchell <davem@​iabyn.com>
Date​: Mon Feb 27 13​:15​:31 2017 +0000

S_do_op_dump_bar()​: don't print TRANS op_pv field

My recent commit v5.25.9-32-gabd07ec made dump.c display the op_pv
string of OP_NEXT, OP_TRANS etc ops. However, for
OP_TRANS/OP_TRANSR,
the string is basically a 256-byte potentially non null-temrinated
array.
This was causing a buffer read overrun and garbage to be displayed.

The simple solution is to only display the address but not contents
for a trans op. OP_NEXT ec labels continue to be displayed.

Focusing first on the variant without 'use integer;' ...

While I get a slowdown from 5.24.1 to HEAD of blead, the slowdown is
not as great as yours and I don't find evidence that the slowdown is
caused (solely) by the commit you identified. Please see
attachments.

Thank you very much.

In addition, these results may be very platform-specific. Please find
attached results from running the same program in a FreeBSD-10.3 VM.
There was significant performance improvement between 5.20.3 and
5.24.1 and a slight (probably not significant) improvement between
5.24.1 and HEAD.

Correction​: slight decline in performance between 5.24.1 and HEAD.

--
James E Keenan (jkeenan@​cpan.org)

@p5pRT
Copy link
Author

p5pRT commented May 13, 2017

From @iabyn

On Fri, May 12, 2017 at 07​:11​:43PM -0700, James E Keenan via RT wrote​:

The following snippet loses about 20% speed between 5.25.9 and
5.26.0RC1

use integer;
for my $n (1..2e5) {
my $k = 0;
while (1) {
last unless 0 < ($n -= 3*++$k - 2);
}
}

5.25.9​: 3.120s
5.26.0​: 3.745s

For some reason the slowdown is less without use integer​:

5.25.9​: 3.200s
5.26.0​: 3.387s

Bisect on the same repo and config.sh as this perlbug says​:

commit f49e846
Author​: David Mitchell <davem@​iabyn.com>
Date​: Mon Feb 27 13​:15​:31 2017 +0000

S_do_op_dump_bar()​: don't print TRANS op_pv field

I think you are just seeing noise.

That commit is a small change to debugging code which is never called by
your benchmark. Often small unrelated changes alter the cache alignment of
particular pieces of hot code, which may temporarily make particular
benchmark programs faster or slower.

I ran your program under 'perf stat -r 10' and captured the total CPU
cycles used, which tends to be a bit more accurate than time since CPU
frequencies can dynamically vary. I got​:

with use integer​:

  5.24.0 11,154,909,863 cycles
  5.24.1 11,189,922,927 cycles
  5.25.0 11,216,097,130 cycles
  5.25.1 13,496,102,427 cycles
  5.25.2 13,564,643,865 cycles
  5.25.3 11,226,142,415 cycles
  5.25.4 11,358,901,129 cycles
  5.25.5 13,518,850,629 cycles
  5.25.6 11,228,134,664 cycles
  5.25.7 11,462,124,884 cycles
  5.25.8 11,237,975,111 cycles
  5.25.9 11,371,753,057 cycles
  5.25.10 13,471,687,745 cycles
  5.25.11 11,431,149,797 cycles
  5.25.12 12,436,185,922 cycles
  5.26.0-RC1 11,291,035,383 cycles

without use integer​:

  5.24.0 11,574,608,582 cycles
  5.24.1 11,633,797,792 cycles
  5.25.0 11,595,347,689 cycles
  5.25.1 13,658,320,154 cycles
  5.25.2 13,719,273,303 cycles
  5.25.3 11,432,351,683 cycles
  5.25.4 11,504,944,237 cycles
  5.25.5 14,315,021,003 cycles
  5.25.6 11,437,100,365 cycles
  5.25.7 11,831,697,493 cycles
  5.25.8 11,378,569,169 cycles
  5.25.9 16,777,124,920 cycles
  5.25.10 14,067,256,508 cycles
  5.25.11 11,490,533,424 cycles
  5.25.12 11,657,785,177 cycles
  5.26.0-RC1 11,450,410,961 cycles

For me, the headline figure would be that without 'use integer', RC1 is
30% *faster* than 5.25.9. In practice its just noise.

--
I before E. Except when it isn't.

@p5pRT
Copy link
Author

p5pRT commented May 15, 2017

From s.schoeling@linet-services.de

On Sat, 13 May 2017 11​:01​:41 -0700
"Dave Mitchell via RT" <perlbug-followup@​perl.org> wrote​:

I think you are just seeing noise.

That commit is a small change to debugging code which is never called by
your benchmark. Often small unrelated changes alter the cache alignment of
particular pieces of hot code, which may temporarily make particular
benchmark programs faster or slower.

[...]

For me, the headline figure would be that without 'use integer', RC1 is
30% *faster* than 5.25.9. In practice its just noise.

May very well be, yes.

Normally I'd take more time to investigate, but since it's RC already, I went for report first. This machine has a comparatively old gcc and that has bitten me before.

--
Sven Schöling

@p5pRT
Copy link
Author

p5pRT commented May 16, 2017

From @xsawyerx

On 05/15/2017 10​:29 AM, Sven Schöling wrote​:

On Sat, 13 May 2017 11​:01​:41 -0700
"Dave Mitchell via RT" <perlbug-followup@​perl.org> wrote​:

I think you are just seeing noise.

That commit is a small change to debugging code which is never called by
your benchmark. Often small unrelated changes alter the cache alignment of
particular pieces of hot code, which may temporarily make particular
benchmark programs faster or slower.

[...]

For me, the headline figure would be that without 'use integer', RC1 is
30% *faster* than 5.25.9. In practice its just noise.
May very well be, yes.

Normally I'd take more time to investigate, but since it's RC already, I went for report first. This machine has a comparatively old gcc and that has bitten me before.

No worries. Thank you for reporting!

I believe we can close this ticket, then?

@p5pRT
Copy link
Author

p5pRT commented May 17, 2017

From s.schoeling@linet-services.de

I believe we can close this ticket, then?

From my point of view​: yes.

--
Sven Schöling

@p5pRT p5pRT closed this as completed May 17, 2017
@p5pRT
Copy link
Author

p5pRT commented May 17, 2017

@xsawyerx - Status changed from 'open' to 'rejected'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant