Reports from the puppet 3.0 migration front

[David Schmitt]

Hi,

I've just upgraded my local test master to 3.0 and wanted to share the ups
and downs.

* The upgrade went as smooth as could be expected: config.ru migration
tripped me up, but was documented.
* There were still unexpected differences in behaviour which were not
warned by 2.7. In my case I was inspecting variables in templates and in
3.0 scope.lookupvar now returns nil in some cases.
* Compilation times for my biggest testcase (~3000 collected resources)
dropped from ~110 seconds to ~70 seconds.
* Agent runtime sadly did not improve beyond this:
Nov 12 12:43:31 inhas60228 puppet-master[23884]: Compiled catalog for
inhas60228.eu.boehringer.com in environment david in 78.16 seconds
[...]
Nov 12 12:46:58 inhas60228 puppet-agent[32596]: Caching catalog for
inhas60228.eu.boehringer.com
Nov 12 12:47:36 inhas60228 puppet-agent[32596]: Applying configuration
version '1352720534'
[...]
Nov 12 12:49:47 inhas60228 puppet-agent[32596]: Finished catalog run
in 131.95 seconds

Note that this is a noop run, and much of the time is already spent
waiting for the catalog and caching it.




Keep up the good work,
David

[R.I.Pienaar]

----- Original Message -----
> From: "David Schmitt" <da...@dasz.at>
> To: "Puppet dev" <puppe...@googlegroups.com>
> Sent: Monday, November 12, 2012 12:06:17 PM
> Subject: [Puppet-dev] Reports from the puppet 3.0 migration front
>
> Hi,
>
> I've just upgraded my local test master to 3.0 and wanted to share
> the ups
> and downs.
>
> * The upgrade went as smooth as could be expected: config.ru
> migration
> tripped me up, but was documented.
> * There were still unexpected differences in behaviour which were
> not
> warned by 2.7. In my case I was inspecting variables in templates and
> in
> 3.0 scope.lookupvar now returns nil in some cases.
> * Compilation times for my biggest testcase (~3000 collected
> resources) dropped from ~110 seconds to ~70 seconds.

Is this with traditional stored configs or with PuppetDB?

[Brice Figureau]

On Mon, 2012-11-12 at 13:06 +0100, David Schmitt wrote:
> Hi,
>
> I've just upgraded my local test master to 3.0 and wanted to share the ups
> and downs.
>
> * The upgrade went as smooth as could be expected: config.ru migration
> tripped me up, but was documented.
> * There were still unexpected differences in behaviour which were not
> warned by 2.7. In my case I was inspecting variables in templates and in
> 3.0 scope.lookupvar now returns nil in some cases.
> * Compilation times for my biggest testcase (~3000 collected resources)
> dropped from ~110 seconds to ~70 seconds.
> * Agent runtime sadly did not improve beyond this:
> Nov 12 12:43:31 inhas60228 puppet-master[23884]: Compiled catalog for
> inhas60228.eu.boehringer.com in environment david in 78.16 seconds
> [...]
> Nov 12 12:46:58 inhas60228 puppet-agent[32596]: Caching catalog for
> inhas60228.eu.boehringer.com
> Nov 12 12:47:36 inhas60228 puppet-agent[32596]: Applying configuration
> version '1352720534'
> [...]
> Nov 12 12:49:47 inhas60228 puppet-agent[32596]: Finished catalog run
> in 131.95 seconds

Well, apparently caching catalog is taking around 38 seconds, which
should be compared to what it took beforehand (you didn't paste your
previours catalog run for this host). This time is not accounted in the
catalog run itself, and I believe that's where the agent is now faster,
so I don't expect you'll see large catalog run time decrease.
This catalog run time is mostly driven by the resource you're managing,
and there's no magical bullet in Puppet 3.0 that automatically make
calls to the package manager, files, users or services dramatically
faster...
--
Brice Figureau
Follow the latest Puppet Community evolutions on www.planetpuppet.org!

[David Schmitt]

The run with 2.7.19 takes around ten minutes wallclock time. 3.0.1 takes
around nine minutes wallclock for a complete "puppet agent --test". The
difference is approximately the time saved on master compiling the
catalog. I'm not concerned about the two minutes spent actually managing
3000 resources (~0.04s per resource). I'm concerned about the other
seven minutes overhead.

On 12.11.2012 13:17, R.I.Pienaar wrote:>
> Is this with traditional stored configs or with PuppetDB?

PuppetDB. The compilation took *MUCH* longer with mysql.



Best Regards, David

[Luke Kanies]

Any idea what that other seven minutes is?

That seems completely pathalogical.

--
Luke Kanies | http://about.me/lak | http://puppetlabs.com/ | +1-615-594-8199

[David Schmitt]

On Tue, 13 Nov 2012 11:08:57 -0800, Luke Kanies <lu...@puppetlabs.com>
wrote:

>> The run with 2.7.19 takes around ten minutes wallclock time. 3.0.1
takes
>> around nine minutes wallclock for a complete "puppet agent --test". The
>> difference is approximately the time saved on master compiling the
>> catalog. I'm not concerned about the two minutes spent actually
managing
>> 3000 resources (~0.04s per resource). I'm concerned about the other
seven
>> minutes overhead.
>
> Any idea what that other seven minutes is?
>
> That seems completely pathalogical.

I'm still scratching at the surface. I've attached the complete --verbose
--noop log from master and agent.

Since I've got no comparison, perhaps one of you can point out something.



Best Regards, David

[Brice Figureau]

Hi,

Let's try to answer the question.

Looking at the log:
07:43:28 agent starts
07:43:30 agent has finished pluginsync
07:43:33 master starts catalog compilation
07:44:48 master has finished compilation (it took 75.51 seconds which is
coherent)
07:49:28 agent starts applying the catalog
07:51:00 agent finishes the catalog run (it took 125.23 seconds)

Between those two traces, we have a time span of about 7 minutes 30s.

So everything looks normal:
compilation 75.51
catalog run 125.23
total 3 min 34 s

Then we have the almost 4 minutes hole between compilation is finished
and the agent starting to apply the catalog.

This is where the agent downloads the catalog, unserialize it to ruby
objects from pson, serialize it again to pson, and stores it to disk.

As I (and Peter) said numerous time, this part of the agent lifecycle is
one of the most time consuming. It should now be much better than when
it was serialized in yaml (can you check that your catalog are
serialized as pson on the agent?), but still we're doing an operation
that has no use just because the internal wiring doesn't allow us to
directly write what the agent receives from the catalog.

BTW, if you put the agent in debug mode, it should show how long it took
to serialize/dump the cached catalog. This way we could compare this
time with the total time and see if the time is spent on serialization,
unserialization, download, etc...

HTH,

[Luke Kanies]

> unserialization, download, etc…

If you're using JSON instead of YAML, then you shouldn't see a lot of time in the converting to and from. I can't remember if this is a configurable option in 3.0, or if it defaults to JSON, but if it still defaults to YAML, that could be a huge win very quickly.

[Patrick Carlisle]

On Wed, Nov 14, 2012 at 9:24 AM, Luke Kanies <lu...@puppetlabs.com> wrote:

If you're using JSON instead of YAML, then you shouldn't see a lot of time in the converting to and from.  I can't remember if this is a configurable option in 3.0, or if it defaults to JSON, but if it still defaults to YAML, that could be a huge win very quickly.

It's configurable in 3.0 with the catalog_cache_terminus setting, and defaults to json for the agent. 

[Luke Kanies]

Ah.  

David - can you confirm the catalog is being stored in json instead of yaml?

[David Schmitt]

On 14.11.2012 22:37, Luke Kanies wrote:
> On Nov 14, 2012, at 10:20 AM, Patrick Carlisle <pat...@puppetlabs.com

> <mailto:pat...@puppetlabs.com>> wrote:
>
>>
>>
>> On Wed, Nov 14, 2012 at 9:24 AM, Luke Kanies <lu...@puppetlabs.com
>> <mailto:lu...@puppetlabs.com>> wrote:
>>
>>
>>
>> If you're using JSON instead of YAML, then you shouldn't see a lot
>> of time in the converting to and from. I can't remember if this
>> is a configurable option in 3.0, or if it defaults to JSON, but if
>> it still defaults to YAML, that could be a huge win very quickly.
>>
>>
>> It's configurable in 3.0 with the catalog_cache_terminus setting, and
>> defaults to json for the agent.
>
> Ah.
>
> David - can you confirm the catalog is being stored in json instead of yaml?

Strange. "puppet agent --configprint catalog_cache_terminus" returns
"json", but "find /var/lib/puppet -mtime -1 -ls" after a --test --noop
run doesn't find the cache, so I can't confirm what is actually written
to disk.


Best Regards, David