puppet-lint
puppet-lint copied to clipboard
rodjek
puppet-lint is too slow when parsing manifests with lots of entries
I'm running the most recent version of puppet-lint (2.2.1). I recently had to re-factor a (fairly large) manifest that declared many (~5k) virtual resources because puppet-lint was simply taking an absurd amount of time to run - many minutes, in some cases many hours.
For example:
0 % for i in `ls *.pp | sort -n`; echo -n "$i - " && time puppet-lint $i
1.pp - puppet-lint $i 0.07s user 0.02s system 98% cpu 0.094 total
2.pp - puppet-lint $i 0.08s user 0.02s system 98% cpu 0.095 total
4.pp - puppet-lint $i 0.09s user 0.01s system 98% cpu 0.101 total
8.pp - puppet-lint $i 0.09s user 0.02s system 98% cpu 0.114 total
16.pp - puppet-lint $i 0.12s user 0.02s system 99% cpu 0.143 total
32.pp - puppet-lint $i 0.18s user 0.04s system 99% cpu 0.218 total
64.pp - puppet-lint $i 0.35s user 0.04s system 99% cpu 0.391 total
128.pp - puppet-lint $i 0.80s user 0.08s system 99% cpu 0.876 total
256.pp - puppet-lint $i 2.34s user 0.13s system 99% cpu 2.482 total
512.pp - puppet-lint $i 8.00s user 0.30s system 99% cpu 8.300 total
1024.pp - puppet-lint $i 29.66s user 0.48s system 99% cpu 30.151 total
2048.pp - puppet-lint $i 116.53s user 0.98s system 99% cpu 1:57.53 total
4096.pp - puppet-lint $i 437.12s user 1.93s system 99% cpu 7:19.14 total
8192.pp - (still going as I write this)
It sure looks like exponential growth here. I haven't looked at the code to figure out where this is happening.
I generated these manifests with a simple script:
#!/bin/bash
COUNT=13
for i in `seq 0 $COUNT`; do
NUMBER=$((2**$i))
FILE=$NUMBER.pp
echo "#" > $FILE
echo "class test {" >> $FILE
for j in `seq 1 $NUMBER`; do
echo " file { 'foo${j}': ensure => absent }" >> $FILE
done
echo "}" >> $FILE
done
8192.pp - puppet-lint $i 1771.98s user 3.81s system 99% cpu 29:36.13 total
Note that I acknowledge that the easiest answer to this problem is "don't do this", and I have indeed re-factored my code to not do it anymore, but this still seems like a problem that should be addressed.
Just for comparison's sake, do you see the same slow down with puppet parser validate and rspec-puppet, or is it only puppet-lint?
Rob Nelson
puppet parser validate:
1.pp - puppet parser validate $i 1.39s user 0.12s system 99% cpu 1.524 total 2.pp - puppet parser validate $i 1.39s user 0.13s system 99% cpu 1.527 total 4.pp - puppet parser validate $i 1.39s user 0.11s system 99% cpu 1.510 total 8.pp - puppet parser validate $i 1.39s user 0.12s system 99% cpu 1.517 total 16.pp - puppet parser validate $i 1.40s user 0.12s system 99% cpu 1.519 total 32.pp - puppet parser validate $i 1.40s user 0.13s system 99% cpu 1.527 total 64.pp - puppet parser validate $i 1.38s user 0.13s system 99% cpu 1.512 total 128.pp - puppet parser validate $i 1.45s user 0.12s system 99% cpu 1.578 total 256.pp - puppet parser validate $i 1.48s user 0.15s system 99% cpu 1.628 total 512.pp - puppet parser validate $i 1.50s user 0.12s system 99% cpu 1.629 total 1024.pp - puppet parser validate $i 1.63s user 0.10s system 99% cpu 1.728 total 2048.pp - puppet parser validate $i 1.83s user 0.12s system 99% cpu 1.952 total 4096.pp - puppet parser validate $i 2.27s user 0.12s system 99% cpu 2.395 total 8192.pp - puppet parser validate $i 3.17s user 0.13s system 99% cpu 3.303 total
So yes, it takes longer, but it's still pretty linear.
I don't currently have rspec-puppet installed on this system so I can't test it as easily.
Note that you can witness the same speed with an empty manifest. Just add a few thousand blank lines to your manifest, and you'll speed puppet-lint down immediately.
Just upgraded from 1.1.0 to 2.3.0 and I now experience huge performance issue too. Took several minutes for a node.pp of 3045 lines.
I think I've discovered what caused the slowdown for large manifests: The regex that is used to match a function name (cmp. PR #854) becomes very slow for large inputs. If I'm not mistaken the pathologic behaviour can be golfed down to something like this:
#!/usr/bin/env ruby
string1 = "some line that doesn't match\n" * 1024 * 16
string2 = "some line that doesn't match\n" * 1024 * 1024
## needs some non-trivial character class with a + quantifier to show the difference
re1 = %r{\A([a-zA-Z]+)(?=\()}
re2 = %r{\A([a-zA-Z]+)\(}
print 'Matching string1 with re1 takes: '
start = Time.now
chunk = string1[re1, 1]
puts 10000 * (Time.now - start)
print 'Matching string1 with re2 takes: '
start = Time.now
chunk = string1[re2, 1]
puts 10000 * (Time.now - start)
print 'Matching string2 with re1 takes: '
start = Time.now
chunk = string2[re1, 1]
puts 10000 * (Time.now - start)
print 'Matching string2 with re2 takes: '
start = Time.now
chunk = string2[re2, 1]
puts 10000 * (Time.now - start)
If I run this I get:
Matching string1 with re1 takes: 0.17579
Matching string1 with re2 takes: 3.08462
Matching string2 with re1 takes: 0.046959999999999995
Matching string2 with re2 takes: 194.09687
The faster match for string2 with re1 is probably related to some warmup/caching, but it's obvious that the match with re2 becomes much slower for the longer string.
OOC I tried the same code with perl
#!/usr/bin/env perl
use strict;
use warnings;
use Time::HiRes;
my $string1 = "some line that doesn't match\n" x (1024 * 16);
my $string2 = "some line that doesn't match\n" x (1024 * 1024);
my $re1 = qr/\A([a-zA-Z]+)(?=\()/;
my $re2 = qr/\A([a-zA-Z]+)\(/;
print 'Matching string1 with re1 takes: ';
my $start = Time::HiRes::gettimeofday();
$string1 =~ $re1;
my $end = Time::HiRes::gettimeofday();
print 10000 * ($end - $start), "\n";
print 'Matching string1 with re2 takes: ';
$start = Time::HiRes::gettimeofday();
$string1 =~ $re2;
$end = Time::HiRes::gettimeofday();
print 10000 * ($end - $start), "\n";
print 'Matching string2 with re1 takes: ';
$start = Time::HiRes::gettimeofday();
$string2 =~ $re1;
$end = Time::HiRes::gettimeofday();
print 10000 * ($end - $start), "\n";
print 'Matching string2 with re2 takes: ';
$start = Time::HiRes::gettimeofday();
$string2 =~ $re2;
$end = Time::HiRes::gettimeofday();
print 10000 * ($end - $start), "\n";
... and got a nearly identical result:
Matching string1 with re1 takes: 0.140666961669922
Matching string1 with re2 takes: 3.06844711303711
Matching string2 with re1 takes: 0.03814697265625
Matching string2 with re2 takes: 193.150043487549
At least for Perl 5 I think I (kind of) understand now why the second regex is much slower. Looking at https://perldoc.perl.org/perlreguts.html, running the code in debug mode (https://perldoc.perl.org/re.html#%27debug%27-mode) and glancing at the source code and comments (https://github.com/Perl/perl5/blob/blead/regexec.c#L780) suggest that an optimization of Perl 5's regex engine is harmful in this particular case.
The regex engine tries to be smart and looks if it finds a single ( in the string. If not, there can't be a match and there is no need to evaluate the character class at all. Unfortunately it takes much longer to look at all characters and find out that there is no ( than just applying the regex from the start of the string would take.
$ perl -e 'print $^V, "\n"' # relatively new version has better debug output
v5.28.1
$ perl -e 'my $str = "some line that doesnt match\n" x (1024 * 1024); use re "debug"; $str =~ /\A([a-zA-Z]+)\(/'
Compiling REx "\A([a-zA-Z]+)\("
synthetic stclass "ANYOF[A-Za-z]".
Final program:
1: SBOL /\A/ (2)
2: OPEN1 (4)
4: PLUS (16)
5: ANYOF[A-Za-z] (0)
16: CLOSE1 (18)
18: EXACT <(> (20)
20: END (0)
floating "(" at 1..9223372036854775807 (checking floating) stclass ANYOF[A-Za-z] anchored(SBOL) minlen 2
Matching REx "\A([a-zA-Z]+)\(" against "some line that doesnt match%nsome line that doesnt match%nso"...
Intuit: trying to determine minimum start position...
doing 'check' fbm scan, [1..29360128] gave -1
Did not find floating substr "("...
Match rejected by optimizer
Freeing REx: "\A([a-zA-Z]+)\("
For the first version of the regex the regex engine doesn't try this optimization (and is much faster):
$ perl -e 'my $str = "some line that doesnt match\n" x (1024 * 1024); use re "debug"; $str =~ /\A([a-zA-Z]+)(?=\()/'
Compiling REx "\A([a-zA-Z]+)(?=\()"
synthetic stclass "ANYOF[A-Za-z]".
Final program:
1: SBOL /\A/ (2)
2: OPEN1 (4)
4: PLUS (16)
5: ANYOF[A-Za-z] (0)
16: CLOSE1 (18)
18: IFMATCH[0] (24)
20: EXACT <(> (22)
22: SUCCEED (0)
23: TAIL (24)
24: END (0)
stclass ANYOF[A-Za-z] anchored(SBOL) minlen 1
Matching REx "\A([a-zA-Z]+)(?=\()" against "some line that doesnt match%nsome line that doesnt match%nso"...
0 <> <some line > | 0| 1:SBOL /\A/(2)
0 <> <some line > | 0| 2:OPEN1(4)
0 <> <some line > | 0| 4:PLUS(16)
| 0| ANYOF[A-Za-z] can match 4 times out of 2147483647...
| 0| failed...
Match failed
Freeing REx: "\A([a-zA-Z]+)(?=\()"
If I had to bet, I'd set my money on Ruby's regex engine doing something similiar.
Parsing large manifests should be much faster on HEAD, since https://github.com/rodjek/puppet-lint/pull/854 has been merged. This issue could probably be closed after the next release.
I don't know for sure, but it seems like @rodjek was quite active the last days and the milestone for 2.4.0 looks promising. So if I had to guess, I'd say: soon-ish.
It's out! So, new numbers:
1.pp - puppet-lint $i 0.15s user 0.03s system 88% cpu 0.207 total 2.pp - puppet-lint $i 0.16s user 0.03s system 99% cpu 0.195 total 4.pp - puppet-lint $i 0.10s user 0.02s system 99% cpu 0.128 total 8.pp - puppet-lint $i 0.14s user 0.03s system 99% cpu 0.173 total 16.pp - puppet-lint $i 0.13s user 0.02s system 99% cpu 0.149 total 32.pp - puppet-lint $i 0.19s user 0.03s system 99% cpu 0.223 total 64.pp - puppet-lint $i 0.18s user 0.02s system 99% cpu 0.205 total 128.pp - puppet-lint $i 0.35s user 0.04s system 99% cpu 0.386 total 256.pp - puppet-lint $i 0.41s user 0.02s system 99% cpu 0.426 total 512.pp - puppet-lint $i 0.84s user 0.02s system 99% cpu 0.867 total 1024.pp - puppet-lint $i 1.97s user 0.04s system 99% cpu 2.012 total 2048.pp - puppet-lint $i 5.78s user 0.06s system 99% cpu 5.842 total 4096.pp - puppet-lint $i 21.43s user 0.14s system 99% cpu 21.574 total 8192.pp - puppet-lint $i 88.84s user 0.27s system 99% cpu 1:29.15 total
I think that some of the core issue is still there, but this is certainly a huge improvement.
That's interesting. It seems that now some of the checks become the bottlenecks. When I looked into this issue, I identified parsing as the problematic part. Running something like this shows that parsing time increases linearly with manifest size now (I've added 16384.pp to prove the point better):
$ for file in 1024.pp 2048.pp 4096.pp 8192.pp 16384.pp; do echo -n "$file "; /usr/bin/time -f %e puppet-lint --only-check '' $file; done
1024.pp 0.56
2048.pp 0.88
4096.pp 1.56
8192.pp 2.96
16384.pp 5.62
The slow checks can be found with something like this (for each check the times for checking 1024.pp, 2048.pp and 4096.pp with only this check are printed in that order):
$ time_check() { /usr/bin/time -f %e puppet-lint --only-check $1 $2 2>&1; }
$ while read check; do t1024=$(time_check $check 1024.pp); t2048=$(time_check $check 2048.pp); t4096=$(time_check $check 4096.pp); printf "%-36s %6s %6s %6s\n" $check $t1024 $t2048 $t4096; done < <(puppet-lint --list-checks)
duplicate_params 1.52 5.05 19.44
unquoted_resource_title 0.64 1.06 1.95
ensure_first_param 1.29 3.59 18.05
ensure_not_symlink_target 1.16 3.47 17.42
unquoted_file_mode 1.16 3.51 18.80
file_mode 1.26 4.05 17.84
case_without_default 0.64 1.06 1.92
selector_inside_resource 1.15 3.53 17.77
variable_is_lowercase 0.56 0.93 1.58
variable_contains_dash 0.56 0.90 1.59
class_inherits_from_params_class 0.57 0.90 1.59
variable_scope 0.56 0.91 1.63
names_containing_uppercase 0.57 0.89 1.60
names_containing_dash 0.57 0.92 1.60
right_to_left_relationship 0.56 0.89 1.58
inherits_across_namespaces 0.56 0.89 1.59
arrow_on_right_operand_line 0.60 0.97 1.73
nested_classes_or_defines 0.57 0.92 1.61
parameter_order 0.57 0.90 1.61
autoloader_layout 0.56 0.91 1.61
code_on_top_scope 0.58 0.94 1.67
star_comments 0.57 0.89 1.58
slash_comments 0.56 0.89 1.58
unquoted_node_name 0.56 0.88 1.57
documentation 0.56 0.91 1.61
quoted_booleans 0.57 0.88 1.58
only_variable_string 0.55 0.89 1.59
variables_not_enclosed 0.57 0.90 1.58
double_quoted_strings 0.57 0.89 1.58
single_quote_string_with_variables 0.57 0.89 1.58
puppet_url_without_modules 0.57 0.89 1.60
80chars 0.57 0.92 1.64
trailing_whitespace 0.59 0.90 1.60
2sp_soft_tabs 0.56 0.90 1.66
arrow_alignment 1.16 3.62 17.21
140chars 0.57 0.91 1.64
hard_tabs 0.58 0.93 1.63
It becomes obvious that these checks run exponentially slower with increasing manifest sizes:
- duplicate_params
- ensure_first_param
- ensure_not_symlink_target
- unquoted_file_mode
- file_mode
- selector_inside_resource
- arrow_alignment
For the record: The change in PR #893 didn't have a measurable effect when compiling my code base at $work.
@tskirvin Would you mind to re-run your tests with 2.4.2? Maybe the issue can be closed finally :)
1.pp - puppet-lint $i 0.16s user 0.02s system 98% cpu 0.187 total
2.pp - puppet-lint $i 0.15s user 0.04s system 99% cpu 0.191 total
4.pp - puppet-lint $i 0.11s user 0.02s system 99% cpu 0.122 total
8.pp - puppet-lint $i 0.11s user 0.01s system 99% cpu 0.127 total
16.pp - puppet-lint $i 0.16s user 0.03s system 99% cpu 0.191 total
32.pp - puppet-lint $i 0.15s user 0.02s system 99% cpu 0.171 total
64.pp - puppet-lint $i 0.16s user 0.02s system 99% cpu 0.182 total
128.pp - puppet-lint $i 0.21s user 0.02s system 99% cpu 0.227 total
256.pp - puppet-lint $i 0.30s user 0.02s system 99% cpu 0.322 total
512.pp - puppet-lint $i 0.66s user 0.02s system 99% cpu 0.687 total
1024.pp - puppet-lint $i 0.96s user 0.02s system 99% cpu 0.977 total
2048.pp - puppet-lint $i 1.96s user 0.05s system 99% cpu 2.021 total
4096.pp - puppet-lint $i 4.00s user 0.07s system 99% cpu 4.076 total
8192.pp - puppet-lint $i 8.84s user 0.10s system 99% cpu 8.944 total
That sure looks promising to me! (I love that I'm still running with the same '$i' bug that I put in there back in 2017.)
