# 20 minutes for an empty node: what is happening?

This is the output from running Puppet (--evaltrace) when it has taken over 20 minutes to process an empty node definition.

Robert.

Info: Loading facts Info: Loading facts Notice: Compiled catalog for standby1....uk in environment production in 6.71 seconds Info: Applying configuration version '1426787754' Info: /Schedule[daily]: Starting to evaluate the resource Info: /Schedule[daily]: Evaluated in 0.00 seconds Info: /Schedule[monthly]: Starting to evaluate the resource Info: /Schedule[monthly]: Evaluated in 0.00 seconds Info: /Schedule[hourly]: Starting to evaluate the resource Info: /Schedule[hourly]: Evaluated in 0.00 seconds Info: Stage[main]: Starting to evaluate the resource Info: Stage[main]: Evaluated in 0.00 seconds Info: Class[Main]: Starting to evaluate the resource Info: Class[Main]: Evaluated in 0.00 seconds Info: Node[standby1]: Starting to evaluate the resource Info: Node[standby1]: Evaluated in 0.00 seconds Info: Class[Settings]: Starting to evaluate the resource Info: Class[Settings]: Evaluated in 0.00 seconds Info: Class[Settings]: Starting to evaluate the resource Info: Class[Settings]: Evaluated in 0.00 seconds Info: Node[standby1]: Starting to evaluate the resource Info: Node[standby1]: Evaluated in 0.00 seconds Info: /Schedule[never]: Starting to evaluate the resource Info: /Schedule[never]: Evaluated in 0.00 seconds Info: /Filebucket[puppet]: Starting to evaluate the resource Info: /Filebucket[puppet]: Evaluated in 0.00 seconds Info: /Schedule[weekly]: Starting to evaluate the resource Info: /Schedule[weekly]: Evaluated in 0.00 seconds Info: /Schedule[puppet]: Starting to evaluate the resource Info: /Schedule[puppet]: Evaluated in 0.00 seconds Info: Class[Main]: Starting to evaluate the resource Info: Class[Main]: Evaluated in 0.00 seconds Info: Stage[main]: Starting to evaluate the resource Info: Stage[main]: Evaluated in 0.00 seconds Notice: Finished catalog run in 1119.24 seconds

edit retag close merge delete

Sort by » oldest newest most voted

I think I've tracked this down.

Using "--debug" revealed something that "--evaltrace" did not: the time is being spent loading and saving "state".

Our server is running applications written in Perl, using the Catalyst applications shell. Those applications track user sessions in files created below a "sessions" directory. We have configured Puppet to Tidy the sessions directories, by removing files over 3 days old.

Currently, we have something like 1200 files in the "sessions" directory tree. A few hundred sessions per day. Plausible.

However, /var/lib/puppet/state/state.yaml has four hundred thousand lines related to these session files.

So in its state file, Puppet is keeping a record of every session file it has ever deleted while tidying. It looks like every time puppet starts, it reads all those records in. And every time it finishes, it writes them all back out again, even though the files no longer exist.

If I remove the contents of Puppet's "state" directory, it processes the empty node in "no time at all".

This is quite astonishing behaviour, and I cannot see how to change it.

AAAAAARGH!

more

The simplest solution is to use a cron to do the work instead of Puppet. Puppet definitely has some weaknesses when it comes to large scale file manipulations. Also Puppet likes to log so you know what's going on. In this case you really don't care. You might consider opening a bug with this info.

cron { 'clean_sessions':
command => 'find /path/to/sessions/ -mtime +3 -type f -name "*.sess" -print0 | xargs -0 -r rm > /dev/null 2>&1',
user    => 'app_user',
minute  => 20,
}

more

Thanks for responding. Cron and find looks like the way to go. I think the behaviour IS a bug, and I considered reporting it as such, but the page you linked to is clearly not set up to encourage ordinary users submitting bug reports...

( 2015-03-22 09:18:58 -0500 )edit

Encouraging or not that's the correct link.

( 2015-03-22 13:42:41 -0500 )edit