About | FAQ | Help
Ask Your Question

Help me track/improve performance

asked 2018-05-04 10:00:12 -0500

erichymowitz gravatar image

updated 2018-05-07 07:56:57 -0500

Greetings. I'm having some performance issues on my puppet master. The logs that I have are pretty sparse, so I was hoping that somebody might give me a push.

My puppet master is also an agent, using itself as the master, and I'm seeing these recent times:

Fri May 04 12:33:04 +0000 2018 Puppet (notice): Finished catalog run in 416.44 seconds
Fri May 04 13:02:51 +0000 2018 Puppet (notice): Finished catalog run in 405.27 seconds
Fri May 04 13:32:59 +0000 2018 Puppet (notice): Finished catalog run in 411.34 seconds
Fri May 04 14:03:05 +0000 2018 Puppet (notice): Finished catalog run in 417.27 seconds

The first thing I notice that's odd is that my debug log runs from 14:21:15 to 14:30:33 (9 min 18 seconds) but the log entry says

[2018-05-04 14:30:33] Notice: Finished catalog run in 449.55 seconds

which is closer to 7 min 30 seconds. Not sure why there's a discrepancy there.

Here's the biggest thing I'm seeing in my debug logs:

[2018-05-04 14:21:18] Debug: Finishing transaction 69836323601480  
[2018-05-04 14:22:27] Debug: Loaded state in 68.90 seconds

[2018-05-04 14:23:03] Debug: Creating default schedules
[2018-05-04 14:25:05] Debug: Loaded state in 121.80 seconds

[2018-05-04 14:27:02] Debug: Finishing transaction 69836161429580
[2018-05-04 14:27:02] Debug: Storing state
[2018-05-04 14:30:33] Debug: Stored state in 210.60 seconds

This accounts for just over 400 seconds (6 min 40 sec). Should these steps be taking this long? Is there something I can do to speed these up and/or to track what is going on?



I don't see anything out of the ordinary in last_run_summary.yaml

    total: 41
    success: 41
    failure: 0
    config_retrieval: 7.02358293533325
    total: 37.4587069353332
    file: 21.355036

I don't think my version of puppet (3.8.7) has the --profile option. I don't see any obvious difference in the output.

You're probably right about system resources. The master is a VM, and it might be fighting for resources. The VM has 8GB RAM, and puppet is using 1.5G, so it might be swapping.

25902 root      20   0 1516m 1.4g 4856 R 99.2 17.6   7:54.90 puppet

vmstat is leading me to look at disk i/o and my throughput, so ...

Thank you very much.

edit retag flag offensive close merge delete

1 Answer

Sort by ยป oldest newest most voted

answered 2018-05-07 03:11:57 -0500

First try to :

cat /opt/puppetlabs/puppet/cache/state/last_run_summary.yaml

to see more details on the time Puppet has spent in its various operations and when applying each resource type. You can post it here for some feedback on it, but it should give you some basic ideas.

Thinks to look at are: - Config time retrieval (how much time the clients spend waiting for a catalog from the server) - Time spent for applying each resource type (it's not uncommon to have some resource types, typically execs, which may take some time to run, and if there are many of them in a catalog, this time is multiplied.

You can use also the profile command line option (coupled with debug) to get more details on the time spent for for each resource :

puppet agent -t --profile --debug

(curiously I just tested it on a Puppet 4.10.5 node and didn't see any profiling info, so I'm not 100% sure this is still working).

Given the output of your debug, I'd also definitively check the system's resources (top, vmstat or similar) during a Puppet run: the system might be swapping like hell during the puppet agent run on the master or have a lot of processes in the run queue.

edit flag offensive delete link more


Thanks for the tips. I updated my question, and I think you're right, system resources (especially disk i/o) are most likely my problem.

erichymowitz gravatar imageerichymowitz ( 2018-05-07 07:57:26 -0500 )edit

Your Answer

Please start posting anonymously - your entry will be published after you log in or create a new account.

Add Answer

Question Tools

1 follower


Asked: 2018-05-04 10:00:12 -0500

Seen: 126 times

Last updated: May 07