Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.bugs.dist > #771194 > unrolled thread

Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server

Back to article view | Back to linux.debian.bugs.dist

Contents

  Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server Leszek Dubiel <leszek.dubiel@dubielvitrum.pl> - 2016-10-02 19:00 +0200
    Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server Niko Tyni <ntyni@debian.org> - 2016-10-02 21:50 +0200
      Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server gregor herrmann <gregoa@debian.org> - 2016-10-02 22:50 +0200
        Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server Niko Tyni <ntyni@debian.org> - 2016-10-02 23:10 +0200
          Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server gregor herrmann <gregoa@debian.org> - 2016-10-02 23:20 +0200
          Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server Niko Tyni <ntyni@debian.org> - 2016-10-03 21:30 +0200
            Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server Niko Tyni <ntyni@debian.org> - 2016-10-03 22:30 +0200
      Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server Leszek Dubiel <leszek.dubiel@dubielvitrum.pl> - 2016-10-02 23:30 +0200

#771194 — Bug#839600: perl: concatenating string instead of sprintf takes all computation power of server

Package: perl
Version: 5.20.2-3+deb8u6
Severity: normal

Dear Maintainer,

*** Reporter, please consider answering these questions, where appropriate ***

I am reading big string from file (2 megabytes), then add parentheses to
the beginning and end of that string, finally do parsing with regular
expressions using \G for continuation. 

>From time to time my server get locked, all computation power was
consumed by that perl script. 

I have asked question on perlmonks:
http://www.perlmonks.org/?node_id=1172994

People were testing program and didn't have the same effect. So it
appeared that this is problem only on my server. I have moved script to
another computer with the same version of Debian (jessie, stable), and
script still did run very slow. Problem dissapeared on new version
(stretch). I have tested on my ubuntu (run fast), and the same hardware
under VirtualBox with fresh installation of Debian Jessie -- script did
run very slow. 

So the problem exists on current debian stable version (jessie), and
doesn't exist on newer versions. 

Here is the test suite to reproduce error: 

https://drive.google.com/file/d/0B9GHvKh0yZKYY0pOUFc5V2hadTg/view?usp=sharing

If error is on your computer, then it runs about 30 seconds. 
If there is no error that it runs only half a second. 

Below there is a program. There are some lines commented out -- if you
uncomment them, then program runs very fast. Why? I don't understand.

###################################

use strict; 
use warnings; 

sub my_parse { 
	my ($a) = @_; 
	$$a =~ /\G\s*+\(/gc or die "paren expected"; 
	while ($$a =~ /\G\s*+([[:alnum:]_]+)\s*+/gc) { 
		if ($$a =~ /\G([-+._[:alnum:]]+|"(?:[^\\"]++|\\[\\"])*+")/gc) { 
			1; 
		} elsif ($$a =~ /\G(?=\()/gc) { 
			my_parse($a); 
		} else { 
			die "wrong value"; 
		}
	}
	$$a =~ /\G\s*+\)\s*+/gc or die "name expected"; 
	return; 
}

my $inp = `cat input.txt`; 

# my $inp = `echo; cat input.txt`; # is fast
# my $inp = `cat input.txt; echo`; # is fast
# my $inp = `sed -n '1,9000p' input.txt`; # is slow
# my $inp = `sed -n '1,8000p' input.txt`; # is fast

my $par = "(" . $inp . ")"; 
# my $par = sprintf "(%s)", $inp; # is fast

my_parse(\$par); 

###################################

The problem seems very strange for me. I have tried to make smaller data
input, but if I cut some lines from input script runs very fast, cut
lines from the beginning, or end, or in the middle. Adding empty line
with "echo" makes it run fast. Sprintf istead of concatenation makes it
fast. 



*** End of the template - remove these template lines ***


-- System Information:
Debian Release: 8.6
  APT prefers stable
  APT policy: (500, 'stable')
Architecture: i386 (i686)

Kernel: Linux 3.16.0-4-686-pae (SMP w/4 CPU cores)
Locale: LANG=pl_PL.UTF-8, LC_CTYPE=pl_PL.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages perl depends on:
ii  dpkg          1.17.27
ii  libbz2-1.0    1.0.6-7+b3
ii  libc6         2.19-18+deb8u6
ii  libdb5.3      5.3.28-9
ii  libgdbm3      1.8.3-13.1
ii  perl-base     5.20.2-3+deb8u6
ii  perl-modules  5.20.2-3+deb8u6
ii  zlib1g        1:1.2.8.dfsg-2+b1

Versions of packages perl recommends:
ii  netbase  5.3
pn  rename   <none>

Versions of packages perl suggests:
pn  libterm-readline-gnu-perl | libterm-readline-perl-perl  <none>
pn  make                                                    <none>
pn  perl-doc                                                <none>

-- no debconf information

[toc] | [next] | [standalone]

#771216

Control: found -1 5.24.1~rc3-3

On Sun, Oct 02, 2016 at 06:40:32PM +0200, Leszek Dubiel wrote:
> Package: perl
> Version: 5.20.2-3+deb8u6
> Severity: normal
> 
> Dear Maintainer,
> 
> >From time to time my server get locked, all computation power was
> consumed by that perl script. 
 
> People were testing program and didn't have the same effect. So it
> appeared that this is problem only on my server. I have moved script to
> another computer with the same version of Debian (jessie, stable), and
> script still did run very slow. Problem dissapeared on new version
> (stretch). I have tested on my ubuntu (run fast), and the same hardware
> under VirtualBox with fresh installation of Debian Jessie -- script did
> run very slow. 
> 
> So the problem exists on current debian stable version (jessie), and
> doesn't exist on newer versions. 

I see this on current sid/amd64 (Perl 5.24) too fwiw, and also in an
amd64 chroot with Perl 5.22. I've no idea why it goes away for you on
stretch. Can you confirm that? Are you only testing on i386 or on amd64
as well?

It looks like the difference between
  $par = "(" . $inp . ")"; # is slow
and
  $par = sprintf "(%s)", $inp; # is fast
internally is that the first one uses copy on write semantics, meaning
it doesn't have to copy the whole string in memory. Of course, this
is supposed to improve performance rather than degrade it.

AFAICS the regexp behaviour stays unchanged, it's just the performance
that drops. I tried some debugging with 'debugperl -Dr' but it mostly
hides the problem by slowing down the execution by itself.

It would be nice to distill the issue to a smaller test case but it's
rather sensitive to the input as you noted so that doesn't seem to be
easy.

Thanks for the report, will try to investigate more.
-- 
Niko Tyni   ntyni@debian.org

[toc] | [prev] | [next] | [standalone]

#771226

[Multipart message — attachments visible in raw view] — view raw

On Sun, 02 Oct 2016 22:44:35 +0300, Niko Tyni wrote:

> > So the problem exists on current debian stable version (jessie), and
> > doesn't exist on newer versions. 
> I see this on current sid/amd64 (Perl 5.24) too fwiw, and also in an
> amd64 chroot with Perl 5.22. I've no idea why it goes away for you on
> stretch. Can you confirm that? Are you only testing on i386 or on amd64
> as well?

I don't see this on sid (amd64):

% for i in $(seq 1 100); time perl run_tests.pl 
[..]
perl run_tests.pl  0.08s user 0.01s system 98% cpu 0.093 total
perl run_tests.pl  0.15s user 0.00s system 98% cpu 0.158 total

(These are the fastest and the slowest of the 100 runs.)


Cheers,
gregor

-- 
 .''`.  Homepage https://info.comodo.priv.at/ - OpenPGP key 0xBB3A68018649AA06
 : :' : Debian GNU/Linux user, admin, and developer -  https://www.debian.org/
 `. `'  Member of VIBE!AT & SPI, fellow of the Free Software Foundation Europe
   `-   NP: Bettina Wegner: Ach, wenn ich doch als Mann auf diese Welt gekommen wär

[toc] | [prev] | [next] | [standalone]

#771228

On Sun, Oct 02, 2016 at 10:38:28PM +0200, gregor herrmann wrote:
> On Sun, 02 Oct 2016 22:44:35 +0300, Niko Tyni wrote:
> 
> > > So the problem exists on current debian stable version (jessie), and
> > > doesn't exist on newer versions. 
> > I see this on current sid/amd64 (Perl 5.24) too fwiw, and also in an
> > amd64 chroot with Perl 5.22. I've no idea why it goes away for you on
> > stretch. Can you confirm that? Are you only testing on i386 or on amd64
> > as well?
> 
> I don't see this on sid (amd64):
> 
> % for i in $(seq 1 100); time perl run_tests.pl 
> [..]
> perl run_tests.pl  0.08s user 0.01s system 98% cpu 0.093 total
> perl run_tests.pl  0.15s user 0.00s system 98% cpu 0.158 total
> 
> (These are the fastest and the slowest of the 100 runs.)

Sorry, should have said I see it with the 'sed -n '1,9000p'
line uncommented.

It seems to have to do with the size of the input file rather
than its contents, but I'm not quite sure yet.
-- 
Niko Tyni   ntyni@debian.org

[toc] | [prev] | [next] | [standalone]

#771232

[Multipart message — attachments visible in raw view] — view raw

On Sun, 02 Oct 2016 23:59:12 +0300, Niko Tyni wrote:

> > > I see this on current sid/amd64 (Perl 5.24) too fwiw, and also in an
> > > amd64 chroot with Perl 5.22. I've no idea why it goes away for you on
> > > stretch. Can you confirm that? Are you only testing on i386 or on amd64
> > > as well?
> > I don't see this on sid (amd64):
> Sorry, should have said I see it with the 'sed -n '1,9000p'
> line uncommented.

Ah :)

Ok, then I get:

% for i in $(seq 1 100); time perl run_tests.pl
perl run_tests.pl  63.54s user 0.02s system 99% cpu 1:03.59 total
perl run_tests.pl  67.39s user 0.15s system 99% cpu 1:07.69 total
perl run_tests.pl  70.04s user 0.08s system 99% cpu 1:10.37 total
^C
 
> It seems to have to do with the size of the input file rather
> than its contents, but I'm not quite sure yet.

Weird indeed.
With "sed -n '1,9001p'" it's fast again; with "sed -n '1,8999p'" as
well?!

Cheers,
gregor

-- 
 .''`.  Homepage https://info.comodo.priv.at/ - OpenPGP key 0xBB3A68018649AA06
 : :' : Debian GNU/Linux user, admin, and developer -  https://www.debian.org/
 `. `'  Member of VIBE!AT & SPI, fellow of the Free Software Foundation Europe
   `-   NP: Bruce Springsteen: Forever Young

[toc] | [prev] | [next] | [standalone]

#771463

[Multipart message — attachments visible in raw view] — view raw

On Sun, Oct 02, 2016 at 11:59:12PM +0300, Niko Tyni wrote:

> It seems to have to do with the size of the input file rather
> than its contents, but I'm not quite sure yet.

It looks like none of the gory regexps are necessary to trigger it.
Here's a short test case, resulting here in

           Rate  concat  assign sprintf
concat   2928/s      --    -94%    -94%
assign  47733/s   1530%      --     -0%
sprintf 47733/s   1530%      0%      --

so showing the 'concat' option has pathologic performance.
It goes away if the length of the base string $s is varied
even slightly, and seems to reappear in 8-byte increments
or decrements. Some of those, like 2**16 - 3, also blow
up the 'sprintf' performance.

The results don't vary much between jessie (Perl 5.20) and sid (5.24)
for me on amd64.

I'll test/bisect this on upstream code next and try to find out if it's
really copy-on-write related or something else.
-- 
Niko Tyni   ntyni@debian.org

[toc] | [prev] | [next] | [standalone]

#771479

Control: forwarded -1 https://rt.perl.org/Ticket/Display.html?id=129802

On Mon, Oct 03, 2016 at 10:23:51PM +0300, Niko Tyni wrote:
> On Sun, Oct 02, 2016 at 11:59:12PM +0300, Niko Tyni wrote:
> 
> > It seems to have to do with the size of the input file rather
> > than its contents, but I'm not quite sure yet.
> 
> It looks like none of the gory regexps are necessary to trigger it.

> I'll test/bisect this on upstream code next and try to find out if it's
> really copy-on-write related or something else.

I've bisected that it regressed with 5.19.7, more precisely
 http://perl5.git.perl.org/perl.git/commit/9ffd39ab75dd662df22fcdafbf7f740838acc898

and filed upstream ticket [perl #129802] about it.
-- 
Niko Tyni   ntyni@debian.org

[toc] | [prev] | [next] | [standalone]

#771233

[Multipart message — attachments visible in raw view] — view raw

> I see this on current sid/amd64 (Perl 5.24) too fwiw, and also in an
> amd64 chroot with Perl 5.22. I've no idea why it goes away for you on
> stretch. Can you confirm that? Are you only testing on i386 or on amd64
> as well?

Problem goes away on "stretch", perl version "subversion 1 (v5.24.1) 
built for x86_64-linux-gnu-thread-multi".
I have checked that many times.


> It looks like the difference between
>    $par = "(" . $inp . ")"; # is slow
> and
>    $par = sprintf "(%s)", $inp; # is fast
> internally is that the first one uses copy on write semantics, meaning
> it doesn't have to copy the whole string in memory. Of course, this
> is supposed to improve performance rather than degrade it.
Yes! I think the same.



> AFAICS the regexp behaviour stays unchanged, it's just the performance
> that drops. I tried some debugging with 'debugperl -Dr' but it mostly
> hides the problem by slowing down the execution by itself.
But you see the difference between "fast" and "slow" lines...
Fast -- half a second, slow -- 30 seconds.
This is dramatic performance impact.


> It would be nice to distill the issue to a smaller test case but it's
> rather sensitive to the input as you noted so that doesn't seem to be
> easy.
I have tried hard -- to cut lines, to cut program to get minimal test 
suite.
But when you remove one line it is slow, when remove 1000 lines still 
slow, when remove 1001 lines gets fast.

Also if you ADD twice that number of lines (double input in size) it 
gets FAST.... :) :)
Twice many data, 50 times faster.

I think I'm lucky to get proper data input to show the problem -- I 
can't craft very small data example to show the problem.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.debian.bugs.dist

csiph-web