What is happening during caching the catalog to disk?
Peter Meier
Hash: SHA1
Hi
so I have the feeling that in 2.6.1rc1++ (actually in general in 2.6) we
got over the problem that caching the catalog down to disk doubles or
triples the memory. So that's nice!
However, I have the feeling that on hosts with huge catalogs it takes a
lot more time than with 0.25.x between the two messages "Caching catalog
to disk" and "Applying Catalog". And to my understanding the only thing
that between these 2 messages should happen is that the catalog is being
written to disk, right?
So when I run the client with --debug I see after "Caching catalog to
disk" a whole bunch of other messages, that are imho totally unrelated
to what puppet should currently do. Here is a little excerpt:
- ---- client ---
info: Loading facts in configured_ntp_servers
debug: catalog supports formats: b64_zlib_yaml dot marshal pson raw
yaml; using pson
debug: Puppet::Type::Package::ProviderRpm: Executing '/bin/rpm --version'
debug: Puppet::Type::Package::ProviderYum: Executing '/bin/rpm --version'
debug: Puppet::Type::Package::ProviderAptrpm: Executing '/bin/rpm -ql rpm'
debug: Puppet::Type::Package::ProviderUrpmi: Executing '/bin/rpm -ql rpm'
info: Caching catalog for foo.bar.ch
debug: /File[/etc/munin/plugin-conf.d/load.conf]/seluser: Found seluser
default 'system_u' for /etc/munin/plugin-conf.d
/load.conf
debug: /File[/etc/munin/plugin-conf.d/load.conf]/selrole: Found selrole
default 'object_r' for /etc/munin/plugin-conf.d
/load.conf
debug: /File[/etc/munin/plugin-conf.d/load.conf]/seltype: Found seltype
default 'etc_t' for /etc/munin/plugin-conf.d/lo
ad.conf
debug:
/File[/var/lib/puppet/modules/shorewall/proxyarp.d/999-footer]/seluser:
Found seluser default 'system_u' for /va
r/lib/puppet/modules/shorewall/proxyarp.d/999-footer
debug:
/File[/var/lib/puppet/modules/shorewall/proxyarp.d/999-footer]/selrole:
Found selrole default 'object_r' for /va
r/lib/puppet/modules/shorewall/proxyarp.d/999-footer
debug:
/File[/var/lib/puppet/modules/shorewall/proxyarp.d/999-footer]/seltype:
Found seltype default 'var_lib_t' for /v
ar/lib/puppet/modules/shorewall/proxyarp.d/999-footer
debug: Puppet::Type::Package::ProviderFink: file /sw/bin/fink does not exist
debug: Puppet::Type::Package::ProviderFreebsd: file /usr/sbin/pkg_add
does not exist
debug: Puppet::Type::Package::ProviderPkg: file /usr/bin/pkg does not exist
debug: Puppet::Type::Package::ProviderRug: file /usr/bin/rug does not exist
debug: Puppet::Type::Package::ProviderAptitude: file /usr/bin/aptitude
does not exist
debug: Puppet::Type::Package::ProviderPortage: file /usr/bin/eix-update
does not exist
debug: Puppet::Type::Package::ProviderNim: file /usr/sbin/nimclient does
not exist
debug: Puppet::Type::Package::ProviderAix: file /usr/bin/lslpp does not
exist
debug: Puppet::Type::Package::ProviderSun: file /usr/sbin/pkgadd does
not exist
debug: Puppet::Type::Package::ProviderUrpmi: file urpmi does not exist
debug: Puppet::Type::Package::ProviderDpkg: file /usr/bin/dpkg does not
exist
debug: Puppet::Type::Package::ProviderOpenbsd: file pkg_add does not exist
debug: Puppet::Type::Package::ProviderHpux: file /usr/sbin/swlist does
not exist
debug: Puppet::Type::Package::ProviderApt: file /usr/bin/apt-get does
not exist
debug: Puppet::Type::Package::ProviderUp2date: file
/usr/sbin/up2date-nox does not exist
debug: Puppet::Type::Package::ProviderPorts: file
/usr/local/sbin/portversion does not exist
debug: Puppet::Type::Package::ProviderSunfreeware: file pkg-get does not
exist
debug: Puppet::Type::Package::ProviderAptrpm: file apt-get does not exist
debug: Puppet::Type::Package::ProviderZypper: file /usr/bin/zypper does
not exist
debug: Puppet::Type::Package::ProviderPortupgrade: file
/usr/local/sbin/portversion does not exist
debug: /File[/var/lib/puppet/modules/shorewall/rules.d/10-NEW]/seluser:
Found seluser default 'system_u' for
/var/lib/puppet/modules/shorewall/rules.d/10-NEW
debug: /File[/var/lib/puppet/modules/shorewall/rules.d/10-NEW]/selrole:
Found selrole default 'object_r' for
/var/lib/puppet/modules/shorewall/rules.d/10-NEW
debug: /File[/var/lib/puppet/modules/shorewall/rules.d/10-NEW]/seltype:
Found seltype default 'var_lib_t' for
/var/lib/puppet/modules/shorewall/rules.d/10-NEW
- ----
and meanwhile it also loads a bunch of metadata from the server:
- --------- server ----------
1.2.3.4 - - [05/Aug/2010:07:51:26 +0200] "GET
/production/file_metadatas/plugins?ignore=---+%0A++-+.svn%0A++-+CVS%0A++-+.git&recurse=true&links=manage&&checksum_type=md5
HTTP/1.1" 200 14103 "-" "-"
1.2.3.4 - - [05/Aug/2010:07:51:57 +0200] "GET
/production/catalog/foo.bar.ch?facts_format=b64_zlib_yaml&facts=[....]
HTTP/1.1" 200 777880 "-" "-"
1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
/production/file_metadata/modules/site-apache/conf.d/foo.bar.ch/vhosts.conf
HTTP/1.1" 404 82 "-" "-"
1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
/production/file_metadata/modules/site-apache/conf.d//vhosts.conf
HTTP/1.1" 404 68 "-" "-"
1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
/production/file_metadata/modules/site-apache/conf.d/CentOS.Final/vhosts.conf
HTTP/1.1" 404 80 "-" "-"
- -----------
and these messages appear definitely during the period when puppet tells
me that it caches the catalog to disk.
so imho it is not only storing the catalog to disk, but it is also loads
various parts of the resources it will later apply.
imho this haven't been the case on 0.25.x or am I wrong?
Anyway the main issue that I have, is that if puppet does now more than
only storing the catalog to disk, then the message should be named
differently. Because on hosts with a large catalog and over a WAN
connection (high latency) it takes now quite long between Caching and
applying and I'm wondering what the heck puppet is currently doing.
But (and that's actually the reason why I write that e-mail) I fear
more, that due to changes in 2.6 (as I don't remember these messages in
0.25.x) in serialization and internal changes to resources, puppet now
loads more than necessary while deserializing the catalog and I even
fear that we do some work twice, as it might also be done while applying
the catalog.
This is pure guess, so I think that I'm wrong, but maybe someone else
can elaborate a bit more or might have a reason for the metadata loading
etc.?
If this is the intended behavior, then I think we should change the info
messages, because when puppet tells me that it's caching the catalog to
disk, I don't expect more than deserialization and writing to disk and
not that it already loads providers and metadata.
But maybe I just have a wrong picture about how internal things work.
cheers pete
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEYEARECAAYFAkxaVisACgkQbwltcAfKi38cqACgr+c/y7LQxbjoi+Uc8gdpCz8w
10IAnj/bpF99aWPz5/ZiMtVMSwX9Xebf
=q9Tx
-----END PGP SIGNATURE-----
Brice Figureau
> Hi
>
> so I have the feeling that in 2.6.1rc1++ (actually in general in 2.6) we
> got over the problem that caching the catalog down to disk doubles or
> triples the memory. So that's nice!
> However, I have the feeling that on hosts with huge catalogs it takes a
> lot more time than with 0.25.x between the two messages "Caching catalog
> to disk" and "Applying Catalog". And to my understanding the only thing
> that between these 2 messages should happen is that the catalog is being
> written to disk, right?
>
> So when I run the client with --debug I see after "Caching catalog to
> disk" a whole bunch of other messages, that are imho totally unrelated
> to what puppet should currently do. Here is a little excerpt:
>
> info: Loading facts in configured_ntp_servers
> debug: catalog supports formats: b64_zlib_yaml dot marshal pson raw
> yaml; using pson
> debug: Puppet::Type::Package::ProviderRpm: Executing '/bin/rpm --version'
> debug: Puppet::Type::Package::ProviderYum: Executing '/bin/rpm --version'
> debug: Puppet::Type::Package::ProviderAptrpm: Executing '/bin/rpm -ql rpm'
> debug: Puppet::Type::Package::ProviderUrpmi: Executing '/bin/rpm -ql rpm'
> info: Caching catalog for foo.bar.ch
> ----
>
> and meanwhile it also loads a bunch of metadata from the server:
>
> 1.2.3.4 - - [05/Aug/2010:07:51:26 +0200] "GET
> /production/file_metadatas/plugins?ignore=---+%0A++-+.svn%0A++-+CVS%0A++-+.git&recurse=true&links=manage&&checksum_type=md5
> HTTP/1.1" 200 14103 "-" "-"
> 1.2.3.4 - - [05/Aug/2010:07:51:57 +0200] "GET
> /production/catalog/foo.bar.ch?facts_format=b64_zlib_yaml&facts=[....]
> HTTP/1.1" 200 777880 "-" "-"
> 1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
> /production/file_metadata/modules/site-apache/conf.d/foo.bar.ch/vhosts.conf
> HTTP/1.1" 404 82 "-" "-"
why does it return 404?
Is it from a multiple sources file type?
> 1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
> /production/file_metadata/modules/site-apache/conf.d//vhosts.conf
> HTTP/1.1" 404 68 "-" "-"
> 1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
> /production/file_metadata/modules/site-apache/conf.d/CentOS.Final/vhosts.conf
> HTTP/1.1" 404 80 "-" "-"
> -----------
>
> and these messages appear definitely during the period when puppet tells
> me that it caches the catalog to disk.
>
> so imho it is not only storing the catalog to disk, but it is also loads
> various parts of the resources it will later apply.
I think this happens after it cached the catalog (see below).
> imho this haven't been the case on 0.25.x or am I wrong?
I don't think this process changed in 2.6.
> Anyway the main issue that I have, is that if puppet does now more than
> only storing the catalog to disk, then the message should be named
> differently. Because on hosts with a large catalog and over a WAN
> connection (high latency) it takes now quite long between Caching and
> applying and I'm wondering what the heck puppet is currently doing.
>
> But (and that's actually the reason why I write that e-mail) I fear
> more, that due to changes in 2.6 (as I don't remember these messages in
> 0.25.x) in serialization and internal changes to resources, puppet now
> loads more than necessary while deserializing the catalog and I even
> fear that we do some work twice, as it might also be done while applying
> the catalog.
>
> This is pure guess, so I think that I'm wrong, but maybe someone else
> can elaborate a bit more or might have a reason for the metadata loading
> etc.?
>
> If this is the intended behavior, then I think we should change the info
> messages, because when puppet tells me that it's caching the catalog to
> disk, I don't expect more than deserialization and writing to disk and
> not that it already loads providers and metadata.
>
> But maybe I just have a wrong picture about how internal things work.
I think this is the normal process, but I can be wrong.
The process is the following:
* the agent retrieves a catalog from the master, during this operation it:
+ deserialize the catalog
+ caches it as yaml (after logging "Caching catalog")
* then the agent converts the catalog resources to their own puppet type (and then loads
the providers too)
* then it evaluates this catalog (and logs "Applying...")
You should put some Puppet.notice statements in lib/puppet/configurer.rb and/or
around lib/puppet/catalog.rb (in the to_ral method), to see where those are coming.
The best would be to use some benchmark statements in the configurer in both 2.6
and 0.25.5 and see if we have some performance regressions.
--
Brice Figureau
My Blog: http://www.masterzen.fr/
Peter Meier
Hash: SHA1
>> 1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
>> /production/file_metadata/modules/site-apache/conf.d/foo.bar.ch/vhosts.conf
>>
>> HTTP/1.1" 404 82 "-" "-"
>
> why does it return 404? Is it from a multiple sources file type?
yes, see separate upcoming mail.
>> [...]
>> But maybe I just have a wrong picture about how internal things
>> work.
>
> I think this is the normal process, but I can be wrong.
>
> The process is the following:
> * the agent retrieves a catalog from the master, during this
> operation it:
> + deserialize the catalog
> + caches it as yaml (after logging "Caching catalog")
> * then the agent converts the catalog resources to their own puppet
> type (and then loads the providers too)
> * then it evaluates this catalog (and logs "Applying...")
>
>
> You should put some Puppet.notice statements in
> lib/puppet/configurer.rb and/or around lib/puppet/catalog.rb (in the
> to_ral method), to see where those are coming.
>
> The best would be to use some benchmark statements in the configurer
> in both 2.6 and 0.25.5 and see if we have some performance
> regressions.
Brice: thanks for that explanation. It makes now more sense and I
shortly checked it with the code and so far it matches your explanation,
so I think everything is fine. :)
cheers pete
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEUEARECAAYFAkxioa0ACgkQbwltcAfKi38LWACfSvkCaTqIh5w7CVz0C70W8Hqc
JtsAl045NABcWmXPDitssWWY6RJRe0Q=
=fUj1
-----END PGP SIGNATURE-----
Peter Meier
Hash: SHA1
So this came up during the note of Brice as well as Luke's comment about
catalog post-processors in the thread "Setting a user's password with
puppet"
>> --------- server ----------
>> 1.2.3.4 - - [05/Aug/2010:07:51:26 +0200] "GET
>> /production/file_metadatas/plugins?ignore=---+%0A++-+.svn%0A++-+CVS%0A++-+.git&recurse=true&links=manage&&checksum_type=md5
>> HTTP/1.1" 200 14103 "-" "-"
>> 1.2.3.4 - - [05/Aug/2010:07:51:57 +0200] "GET
>> /production/catalog/foo.bar.ch?facts_format=b64_zlib_yaml&facts=[....]
>> HTTP/1.1" 200 777880 "-" "-"
>> 1.2.3.4 - - [05/Aug/2010:07:52:12 +0200] "GET
>> /production/file_metadata/modules/site-apache/conf.d/foo.bar.ch/vhosts.conf
>> HTTP/1.1" 404 82 "-" "-"
>
> why does it return 404?
> Is it from a multiple sources file type?
Yes, this is from a multiple sources file and I think the multiple
sources for file types feature is quite a nice thing to write modules
that are nicely configurable:
file{"/etc/apache2/conf.d/${name}":
source => [
"puppet:///modules/site-apache/conf.d/${fqdn}/${name}",
"puppet:///modules/site-apache/conf.d/${apache_cluster_node}/${name}",
"puppet:///modules/site-apache/conf.d/${operatingsystem}.${lsbdistcodename}/${name}",
"puppet:///modules/site-apache/conf.d/${operatingsystem}/${name}",
"puppet:///modules/site-apache/conf.d/${name}",
"puppet:///modules/apache/conf.d/${operatingsystem}.${lsbdistcodename}/${name}",
"puppet:///modules/apache/conf.d/${operatingsystem}/${name}",
"puppet:///modules/apache/conf.d/${name}"
],
}
So such resource definitions lead to an issue, to which I haven't yet
paid that much attention: The client will call the fileserver for each
source up to the first one that hits. At least to get the metadata for
the file resource. Which means that with such a stack of file sources
and a couple of similar sources for file resources you might end up with
a couple hundred metadata calls that end in a 404.
This increases the time spent on file resources, especially on hosts
with high latency.
And here comes Luke's mentioned catalog post_processor into the game:
Actually we already now at compile time which file sources are valid, at
least for all sources with the "puppet:///..." style, as they are lying
aside the manifests we are compiling. So why not, optimize the catalog
that is sent to the client by removing all the sources that will give a
404 on the server anyway? (For safety reasons maybe all up to one last
failing resource, if all fails) This would drastically reduce the calls
to the master and hence speedup clients.
The only problem I currently see is, if a client is using a (local)
cached catalog and somebody addd a file to the source tree on the
master, which source path is removed in the client's cached catalog.
This would require the client to get a new catalog, otherwise the client
wouldn't get the newly added file. However that problem is similar to
the one, that if clients are using a cached catalog and you are moving
files on the master (and adjusting the sources of that resource, but
they don't make it to the client), which will then lead to the issue,
that a client might take the wrong file.
Is this catalog post_processor already something that is usable or is it
so far just an idea?
Any other thoughts?
cheers pete
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEYEARECAAYFAkxiqeYACgkQbwltcAfKi3+RMwCdGod5/IHkct3m+I0KpqWCsfNB
znkAoLJXbuYMiZciIMR4FHJf6zvS/n4Q
=HsIR
-----END PGP SIGNATURE-----
Luke Kanies
It's currently just a concept, but 1) one that we'll definitely be
adding "soon", and 2) one that's not too hard to hack into your own
system.
I've already talked to companies using curl to compile their catalogs,
which means it's pretty straightforward to retrieve a given host's
catalog. It's even easier if you use --compile on the server-side to
do the retrieval. From there, you can do the operations necessary to
perform these modifications, and then return that. Just have a
"simple" web service running that talks to puppetmasterd, modifies the
catalog, and returns it.
Of course, that's not actually that easy in the end. It's probably
easier to add a patch that does what you want. Here's how (basically):
The simplest one-off way is to modify the find() method in lib/puppet/
indirector/catalog/compiler to perform a callback if appropriate, and
then implement that callback. E.g., implement a 'replace-multi-files-
with-one' method that does this kind of querying and modifies the
actual catalog, and call that from there.
This method has to just do a Puppet::FIleServing::File.find on each of
the paths, and remove all but the first one that doesn't thrown an
exception.
Of course, I'm making this seem easy, but it's not, I know.
It feels like the "right" way to do this in the end is a setting that
points to an external program, which we would feed that catalog to and
then replace our copy with the result. I think that external program
would essentially have to be in ruby, though, so it could use our
code, and if that's the case, then the exec seems a waste of effort.
So I don't really know the right way to do this overall.
In summary, I think this (and a bunch of related ideas) is excellent
and I'd love to find a way to implement it. I'd also love to find a
way to make this aspect of Puppet (along with others) seem more like a
pipeline in which it's easy to stick filters, rather than a
complicated system that's tough to jack into.
--
If you would be a real seeker after truth, it is necessary that at
least once in your life you doubt, as far as possible, all things.
-- Rene Descartes
---------------------------------------------------------------------
Luke Kanies -|- http://puppetlabs.com -|- +1(615)594-8199