On Wed, 2013-02-20 at 12:33 +0100, David Schmitt wrote:
> Hi Brice!
> 
> On Wed, 20 Feb 2013 10:56:18 +0100, Brice Figureau
> <[email protected]> wrote:
> > On Wed, 2013-02-20 at 10:11 +0100, David Schmitt wrote:
> >> Hi,
> >> 
> >> meditating over a 13 minute runtime of an agent who's managing 4200
> >> resources, I found this:
> >> 
> >>     -rw-rw---- 1 root root 1.8M Feb 20 09:45
> >> /var/lib/puppet/state/state.yaml
> >> 
> >> I seem to remember that yaml serialization can be a problem. Is there a
> >> way to use json for the state.yaml or should I file a bug on that?
> >> 
> >> 
> >> 
> >> Here's the catalog, already in json, so that seems to work out:
> >> 
> >>     -rw-rw---- 1 root root 6.4M Feb 20 10:06
> >> /var/lib/puppet/client_data/catalog/fqdn.example.com.json
> > 
> > You didn't mention the version of puppet you used (but I believe it's
> > already the 3.x).
> 
> Yes, 3.0.1 is running here. On RHEL 6.3:
> 
>   [root@fqdn ~]# ruby --version
>   ruby 1.8.7 (2011-06-30 patchlevel 352) [x86_64-linux]
> 
> > Can you run with --summarize so that we have a look to where the time is
> > spent (do you manage sloooow resources)?
> > 
> > I'd be suprised if you're spending most of the time in saving the client
> > state, but that would be interesting to check.
> 
> Not all of it. I've reduced the resource count by directly using templates
> instead of file+nagios_service, and this reduced the runtime to 8 minutes.
> I guess I can shave off a few more seconds by converting file+host to a
> template too, but that's chasing pennies.
> 
>   -rw-rw---- 1 root root 4.4M Feb 20 11:42
> /var/lib/puppet/client_data/catalog/fqdn.example.com.json
>   -rw-rw---- 1 root root 1.8M Feb 20 11:44
> /var/lib/puppet/state/state.yaml
> 
> Compile time of the catalog was not impacted by that change, as it is
> completely within a collected define:
> 
> Prior:
> 
>   Feb 20 05:57:48 fqdn puppet-master[15801]: Compiled catalog for
> fqdn.example.com in environment prod in 102.58 seconds
> 
> After:
> 
>   Feb 20 12:14:17 fqdn puppet-master[26630]: Compiled catalog for
> fqdn.example.com in environment david in 115.71 seconds
> 
> 
> Here's the --summarize footer, as well as "time"'s output:
> 
>   Finished catalog run in 108.48 seconds
>   Changes:
>   Events:
>               Total: 14
>                Noop: 14
>   Resources:
>         Out of sync: 14
>               Total: 2709
>             Skipped: 6
>   Time:
>      Nagios hostgroup: 0.00
>          Filebucket: 0.00
>                Tidy: 0.00
>               Mount: 0.00
>      Nagios timeperiod: 0.00
>               Group: 0.00
>                Cron: 0.01
>      Nagios contact: 0.01
>                User: 0.03
>             Yumrepo: 0.03
>              Sshkey: 0.22
>         Nagios host: 0.90
>            Last run: 1361359272
>              Augeas: 2.33
>             Package: 2.88
>      Config retrieval: 401.45

Yep, catalog serialization/deserialization in action...

>               Total: 430.31
>             Service: 5.62
>                Exec: 7.68
>                File: 9.15
>   Version:
>              Puppet: 3.0.1
>              Config: heads/david-0-g60f805f
>   
>   real        9m19.463s
>   user        3m1.637s
>   sys 0m35.450s
> 
> 
> Here's my naive analysis: total runtime is 9m19s (559s). That is 401s
> config retrieval + 108s catalog run time + 50s unaccounted. Of the 401s
> config retrieval, 115s are compile time and 258s are unaccounted for.

Thanks for those figures, this is highly interesting!

So, we need to chase those 258s.
I believe that it comes from:

* downloading the catalog from the master (are you on a lan?, if not try
--http-compression)

* unserializing the pson catalog (this is certainly what takes time,
because it involves creating numerous ruby objects)

* serializing it back to the client_state cache (unfortunately we
apparently can't get rid of this part)

* at the same time managing the state file

Now to really know what exactly takes time, you'll have to add debug
statements in the agent code base.

> PuppetDB and Dashboard are running locally and the host is lightly loaded.
> The PuppetDB dashboard claims 0.06 seconds "Collection Queries" service
> time and 0.07 seconds command "Command Processing". 
> 
> This agent collects approximately 1700 resources in 8-10 queries and
> expands that to ~1900 file and nagios* resources. The rest of the resources
> are "local" configuration, so to say.

Thanks for the detailed analysis :)
-- 
Brice Figureau
Follow the latest Puppet Community evolutions on www.planetpuppet.org!

-- 
You received this message because you are subscribed to the Google Groups 
"Puppet Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to [email protected].
To post to this group, send email to [email protected].
Visit this group at http://groups.google.com/group/puppet-dev?hl=en.
For more options, visit https://groups.google.com/groups/opt_out.


Reply via email to