Skip Menu |
Report information
Id: 131291
Status: rejected
Priority: 0/
Queue: perl5

Owner: Nobody
Requestors: sschoeling [at] linet-services.de
Cc:
AdminCc:

Operating System: (no value)
PatchStatus: (no value)
Severity: low
Type: core
Perl Version: 5.26.0
Fixed In: (no value)



Subject: Slowdown in integer loops
From: sschoeling [...] linet-services.de
To: perlbug [...] perl.org
Date: Fri, 12 May 2017 14:34:01 +0200 (CEST)
Download (untitled) / with headers
text/plain 4.3k
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 f49e84642c2886177a0ec4ddff2ef186df4c6441 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. [Please do not change anything below this line] ----------------------------------------------------------------- --- 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
RT-Send-CC: perl5-porters [...] perl.org
Download (untitled) / with headers
text/plain 1.6k
On Fri, 12 May 2017 12:45:00 GMT, sschoeling@linet-services.de wrote: Show quoted text
> > 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 f49e84642c2886177a0ec4ddff2ef186df4c6441 > 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)
Subject: 131291-slowdown.pl
Download 131291-slowdown.pl
text/x-perl 118b
#use integer; for my $n (1..2e5) { my $k = 0; while (1) { last unless 0 < ($n -= 3*++$k - 2); } }
Subject: 131291-testing-results.txt
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 5d577b6f636aba916a1b0519669de4b2454c68ab # 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 f49e84642c2886177a0ec4ddff2ef186df4c6441^ # configure and build perl $ git show | head -1 commit 41b1e858a075694f88057b9514f5fc78c80b5355 $ ./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 f49e84642c2886177a0ec4ddff2ef186df4c6441 # configure and build perl $ git show | head -1 commit f49e84642c2886177a0ec4ddff2ef186df4c6441 $ ./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 b97ea83254457bb54ffb80694b355111d431712c # 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
RT-Send-CC: perl5-porters [...] perl.org
On Sat, 13 May 2017 01:55:59 GMT, jkeenan wrote: Show quoted text
> 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 f49e84642c2886177a0ec4ddff2ef186df4c6441 > > 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)
Subject: 131291-freebsd-103-results.txt
# 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
RT-Send-CC: perl5-porters [...] perl.org
Download (untitled) / with headers
text/plain 2.3k
On Sat, 13 May 2017 02:11:42 GMT, jkeenan wrote: Show quoted text
> 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 f49e84642c2886177a0ec4ddff2ef186df4c6441 > > > 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)
To: James E Keenan via RT <perlbug-followup [...] perl.org>
From: Dave Mitchell <davem [...] iabyn.com>
CC: perl5-porters [...] perl.org
Subject: Re: [perl #131291] Slowdown in integer loops
Date: Sat, 13 May 2017 19:01:16 +0100
Download (untitled) / with headers
text/plain 2.6k
On Fri, May 12, 2017 at 07:11:43PM -0700, James E Keenan via RT wrote: Show quoted text
> > > 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 f49e84642c2886177a0ec4ddff2ef186df4c6441 > > > 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.
To: perlbug-followup [...] perl.org
From: Sven Schöling <s.schoeling [...] linet-services.de>
Subject: Re: [perl #131291] Slowdown in integer loops
Date: Mon, 15 May 2017 10:29:21 +0200
Download (untitled) / with headers
text/plain 751b
On Sat, 13 May 2017 11:01:41 -0700 "Dave Mitchell via RT" <perlbug-followup@perl.org> wrote: Show quoted text
> 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
From: Sawyer X <xsawyerx [...] gmail.com>
To: Sven Schöling <s.schoeling [...] linet-services.de>, perlbug-followup [...] perl.org
Subject: Re: [perl #131291] Slowdown in integer loops
Date: Tue, 16 May 2017 23:30:53 +0200
Download (untitled) / with headers
text/plain 879b
On 05/15/2017 10:29 AM, Sven Schöling wrote: Show quoted text
> 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?
To: perlbug-followup [...] perl.org
From: Sven Schöling <s.schoeling [...] linet-services.de>
Date: Wed, 17 May 2017 11:04:53 +0200
Subject: Re: [perl #131291] Slowdown in integer loops
Show quoted text
> I believe we can close this ticket, then?
From my point of view: yes. -- Sven Schöling


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

For issues related to this RT instance (aka "perlbug"), please contact perlbug-admin at perl.org