Serious performance issues with Puppet 3.5.x when using Directory Environments

[Antoine Cotten]

Dear Puppet Users community, I would like to report an issue I experience since the first release of Puppet 3.5, and possibly get some input from people who face the same problem (if any).


I run a Puppet environment in which all 48 nodes run CentOS 6.5. I have been using config file-based environments so far without any trouble. When Puppet 3.5.0 was officially released I decided to give give it a try, along with the new Directory Environments feature. I disabled my old-style environment config while making sure my directory tree was correctly set, as described in the "Directory Environments" documentation page.

The problem shows up immediately after I restart httpd: Passenger starts spawning more and more processes which all consume 25% of my machine CPU, reaching a load average of 10+ in less than a minute as soon as the first node requests a catalog. This makes the master unusable, it takes between 200 and 300sec to compile any catalog.


What I have tried:

1. Switching back from Passenger to WEBrick: same performance issue
2. Disabling the puppet service on all nodes, and triggering one single manual Puppet run on a random node: same performance issue
3. Disabling my external node classifier (Foreman): same performance issue
4. Upgrading to Puppet 3.5.1: same performance issue
   
5. Switching back to config-based environments and re-enabling all nodes: no issue, my master behaves normally and the load-average remains under 0.25 constantly

As you might have noticed, this is definitely not a sizing issue. My master has 2GB of RAM and 2 allocated vCPU, but the Puppet master rack process starts consuming all resources as soon as I re-enable Directory Environments.

When I want to use Directory Environments, the only thing I do is commenting the [development] and [production] sections in my puppet.conf file, and adding this to the [main] section: environmentpath = $confdir/environments

Let me describe my configuration:

-----------------puppet.conf--------------
[main]
    logdir = /var/log/puppet.
    rundir = /var/run/puppet
    ssldir = $vardir/ssl
    privatekeydir = $ssldir/private_keys { group = service }
    hostprivkey = $privatekeydir/$certname.pem { mode = 640 }
    autosign       = $confdir/autosign.conf { mode = 664 }

[master]
    autosign       = $confdir/autosign.conf { mode = 664 }
    reports        = foreman
    external_nodes = /etc/puppet/node.rb
    node_terminus  = exec
    ca             = true
    ssldir         = /var/lib/puppet/ssl
    storeconfigs = true
    storeconfigs_backend = puppetdb

[development]
    modulepath     = /etc/puppet/environments/development/modules:/usr/share/puppet/modules
    manifest       = /etc/puppet/environments/development/manifests/site.pp
    config_version =
[production]
    modulepath     = /etc/puppet/environments/production/modules:/usr/share/puppet/modules
    manifest       = /etc/puppet/environments/production/manifests/site.pp
    config_version =

--------------------------------------------------
--------------directory tree--------------
/etc/puppet/environments/
|-- development
|   |-- manifests
|   |   `-- site.pp
|   `-- modules
|       |-- activemq
|       |-- apache
|       |-- apt
|       |-- concat
|       |-- datacat
|       |-- environment
|       |-- epel
|       |-- erlang
|       |-- firewall
|       |-- java
|       |-- java_ks
|       |-- mcollective
|       |-- postfix
|       |-- profiles
|       |-- rabbitmq
|       |-- repos
|       |-- stdlib
|       `-- tomcat
`-- production
    |-- manifests
    |   `-- site.pp
    `-- modules
        |-- activemq
        |-- apache
        |-- apt
        |-- concat
        |-- datacat
        |-- environment
        |-- epel
        |-- erlang
        |-- firewall
        |-- inifile
        |-- java
        |-- java_ks
        |-- mcollective
        |-- mysql
        |-- ntp
        |-- postfix
        |-- postgresql
        |-- profiles
        |-- puppetdb
        |-- rabbitmq
        |-- repos
        |-- stdlib
        |-- tomcat
        `-- vsftpd
--------------------------------------------------

Can anybody reproduce this it on any platform? Thank you in advance for your help!

Toni

[Eric Sorenson]

Hi Toni, this is an interesting report -- can you please run a client against the server with profiling enabled and post the output from the master?

Instructions are here: http://docs.puppetlabs.com/pe/latest/trouble_puppet.html#improving-profiling-and-debugging-of-slow-catalog-compilations

[Antoine Cotten]

Hi Eric,
thank you for pointing me to this feature, and sorry for the answer time.

I managed to outline the problematic parts in the Puppet run: the final POST method takes forever when Directory Environments is enabled (1) and the catalog compilation is overall much slower (1.3./4|5|6/)

I triggered a run on the same node, with and without the feature enabled. Here are the corresponding profiling logs:

-- WITH Directory Environments --
Tue Apr 22 13:47:25 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.1 Found facts: took 0.3345 seconds
Tue Apr 22 13:47:27 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.2 Found node information: took 1.7774 seconds
Tue Apr 22 13:47:27 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.1 Compile: Set node parameters: took 0.0011 seconds
Tue Apr 22 13:47:27 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.2 Compile: Created settings scope: took 0.0169 seconds
Tue Apr 22 13:47:27 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.3 Compile: Evaluated main: took 0.0005 seconds
Tue Apr 22 13:47:28 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.1 Called realize: took 0.0001 seconds
Tue Apr 22 13:47:29 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.1.1 Called template: took 0.0065 seconds
Tue Apr 22 13:47:29 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.1 Called include: took 0.1987 seconds
Tue Apr 22 13:47:30 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.2.1 Called include: took 0.5500 seconds
Tue Apr 22 13:47:30 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.2.2 Called include: took 0.4929 seconds
Tue Apr 22 13:47:30 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.2.3 Called include: took 0.1679 seconds
Tue Apr 22 13:47:30 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.2.4 Called hiera: took 0.0008 seconds
Tue Apr 22 13:47:30 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.2.5 Called create_resources: took 0.0059 seconds
Tue Apr 22 13:47:30 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.2 Called include: took 1.4023 seconds
Tue Apr 22 13:47:31 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.3.1 Called include: took 0.1721 seconds
Tue Apr 22 13:47:31 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.3.2 Called include: took 0.1670 seconds
Tue Apr 22 13:47:31 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.3.3 Called include: took 0.1627 seconds
Tue Apr 22 13:47:31 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.3 Called include: took 0.6955 seconds
Tue Apr 22 13:47:31 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.4 Called include: took 0.2113 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.5.1 Called include: took 0.1720 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.5 Called include: took 0.6649 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.6 Called include: took 0.1743 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.7.1 Called create_resources: took 0.0620 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.7 Called include: took 0.2302 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1.8 Called template: took 0.0035 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2.1 Called include: took 3.7768 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.2 Called include: took 4.2513 seconds
Tue Apr 22 13:47:32 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3.1 Called hiera: took 0.0101 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3.2.1 Called template: took 0.2848 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3.2.2 Called template: took 0.0515 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3.2.3 Called template: took 0.0107 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3.2.4 Called template: took 0.0075 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3.2 Called include: took 1.8237 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.3 Called include: took 2.0044 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.1 Called hiera: took 0.0024 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.2 Called hiera: took 0.0005 seconds
Tue Apr 22 13:47:34 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.3 Called hiera: took 0.0005 seconds
Tue Apr 22 13:47:35 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.4 Called hiera: took 0.0006 seconds
Tue Apr 22 13:47:35 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.5 Called hiera: took 0.0006 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.6 Called include: took 3.5948 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.7 Called file: took 0.0001 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.8 Called defined: took 0.0001 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.9 Called file: took 0.0001 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.10 Called file: took 0.0001 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4.11 Called create_resources: took 0.0348 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.4 Called include: took 3.9831 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4.5 Called include: took 0.1631 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.4 Compile: Evaluated AST node: took 11.3217 seconds
Tue Apr 22 13:47:38 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.5 Compile: Evaluated node classes: took 0.0000 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.1 Evaluated collections: took 0.3247 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.1 Evaluated resource Environment::Users::Sshuser[volk]: took 0.0058 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.2 Evaluated resource Environment::Users::Sshuser[cotten]: took 0.0089 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.3 Evaluated resource Postfix::File[header_checks]: took 0.0012 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.4 Evaluated resource Postfix::File[body_checks]: took 0.0011 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.5 Evaluated resource Postfix::File[canonical_recipient]: took 0.0049 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.6 Evaluated resource Mcollective::Common::Setting[libdir]: took 0.0207 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.7 Evaluated resource Mcollective::Common::Setting[connector]: took 0.0061 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.8 Evaluated resource Mcollective::Common::Setting[securityprovider]: took 0.0064 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.9 Evaluated resource Mcollective::Common::Setting[collectives]: took 0.0045 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.10 Evaluated resource Mcollective::Common::Setting[main_collective]: took 0.0073 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.11.1 Called defined: took 0.0261 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.11.2 Called size: took 0.0000 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.11.3 Called range: took 0.0000 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.11 Evaluated resource Mcollective::Soft_include[::mcollective::common::config::connector::activemq]: took 0.7317 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.12.1 Called defined: took 0.0102 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.12 Evaluated resource Mcollective::Soft_include[::mcollective::common::config::securityprovider::ssl]: took 0.0130 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.13.1 Called template_body: took 0.0002 seconds
Tue Apr 22 13:47:39 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.13 Evaluated resource Datacat[mcollective::server]: took 0.0124 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.14 Evaluated resource Mcollective::Server::Setting[classesfile]: took 0.0096 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.15 Evaluated resource Mcollective::Server::Setting[daemonize]: took 0.0054 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.16 Evaluated resource Mcollective::Server::Setting[logfile]: took 0.0128 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.17 Evaluated resource Mcollective::Server::Setting[loglevel]: took 0.0061 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.18.1 Called defined: took 0.0227 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.18.2 Called size: took 0.0000 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.18.3 Called range: took 0.0000 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.18 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::connector::activemq]: took 0.2803 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.19.1 Called defined: took 0.0303 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.19 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::securityprovider::ssl]: took 0.2944 seconds
Tue Apr 22 13:47:40 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.20.1 Called defined: took 0.0223 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.20.2 Called template: took 0.0232 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.20 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::factsource::yaml]: took 0.6268 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.21.1 Called defined: took 0.0108 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.21 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::registration::]: took 0.0115 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.22.1 Called defined: took 0.0242 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.22 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::rpcauditprovider::logfile]: took 0.2607 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.23.1 Called defined: took 0.0246 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.23 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::rpcauthprovider::action_policy]: took 0.2664 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.24 Evaluated resource Mcollective::Common::Setting[plugin.activemq.heartbeat_interval]: took 0.0042 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2.25 Evaluated resource Mcollective::Plugin[misc]: took 0.0120 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1.2 Evaluated definitions: took 2.6435 seconds
Tue Apr 22 13:47:41 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.1 Iterated (1) on generators: took 2.9685 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.1.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.1 Evaluated resource Mcollective::Setting[mcollective::common::setting libdir]: took 0.3161 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.2.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.2 Evaluated resource Mcollective::Setting[mcollective::common::setting connector]: took 0.0049 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.3.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.3 Evaluated resource Mcollective::Setting[mcollective::common::setting securityprovider]: took 0.0030 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.4.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.4 Evaluated resource Mcollective::Setting[mcollective::common::setting collectives]: took 0.0010 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.5.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.5 Evaluated resource Mcollective::Setting[mcollective::common::setting main_collective]: took 0.0051 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.6 Evaluated resource Mcollective::Common::Setting[direct_addressing]: took 0.0070 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.7 Evaluated resource Mcollective::Common::Setting[plugin.activemq.base64]: took 0.0075 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.8 Evaluated resource Mcollective::Common::Setting[plugin.activemq.randomize]: took 0.0111 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.9 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.size]: took 0.0037 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.10 Evaluated resource Mcollective::Common::Config::Connector::Activemq::Hosts_iteration[1]: took 0.3711 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.11.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.11 Evaluated resource Mcollective::Setting[mcollective::server::setting classesfile]: took 0.0012 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.12.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.12 Evaluated resource Mcollective::Setting[mcollective::server::setting daemonize]: took 0.0050 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.13.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.13 Evaluated resource Mcollective::Setting[mcollective::server::setting logfile]: took 0.0010 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.14.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.14 Evaluated resource Mcollective::Setting[mcollective::server::setting loglevel]: took 0.0057 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.15 Evaluated resource Mcollective::Server::Config::Connector::Activemq::Hosts_iteration[1]: took 0.3622 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.16 Evaluated resource Mcollective::Server::Setting[plugin.ssl_client_cert_dir]: took 0.0078 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.17 Evaluated resource Mcollective::Server::Setting[plugin.ssl_server_public]: took 0.0076 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.18 Evaluated resource Mcollective::Server::Setting[plugin.ssl_server_private]: took 0.0076 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.19 Evaluated resource Mcollective::Server::Setting[factsource]: took 0.0116 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.20 Evaluated resource Mcollective::Server::Setting[plugin.yaml]: took 0.0028 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.21 Evaluated resource Mcollective::Server::Setting[rpcauditprovider]: took 0.0036 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.22 Evaluated resource Mcollective::Server::Setting[rpcaudit]: took 0.0025 seconds
Tue Apr 22 13:47:42 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.23 Evaluated resource Mcollective::Server::Setting[plugin.rpcaudit.logfile]: took 0.0047 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.24 Evaluated resource Mcollective::Plugin[actionpolicy]: took 0.0075 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.25 Evaluated resource Mcollective::Server::Setting[rpcauthorization]: took 0.0078 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.26 Evaluated resource Mcollective::Server::Setting[rpcauthprovider]: took 0.0104 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.27 Evaluated resource Mcollective::Server::Setting[plugin.actionpolicy.allow_unconfigured]: took 0.0176 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.28.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1.28 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.heartbeat_interval]: took 0.0014 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2.1 Evaluated definitions: took 1.2385 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.2 Iterated (2) on generators: took 1.2453 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.1.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.1 Evaluated resource Mcollective::Setting[mcollective::common::setting direct_addressing]: took 0.0012 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.2.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.2 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.base64]: took 0.0073 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.3.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.3 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.randomize]: took 0.0011 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.4.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.4 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.size]: took 0.0085 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.5 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.host]: took 0.0150 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.6 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.port]: took 0.0150 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.7 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.user]: took 0.0061 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.8 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.password]: took 0.0109 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.9 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.ssl]: took 0.0093 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.10 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.ssl.ca]: took 0.0066 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.11 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.ssl.fallback]: took 0.0093 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.12 Evaluated resource Mcollective::Server::Setting[plugin.activemq.pool.1.ssl.cert]: took 0.0039 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.13 Evaluated resource Mcollective::Server::Setting[plugin.activemq.pool.1.ssl.key]: took 0.0153 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.14.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.14 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.ssl_client_cert_dir]: took 0.0011 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.15.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.15 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.ssl_server_public]: took 0.0017 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.16.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.16 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.ssl_server_private]: took 0.0048 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.17.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.17 Evaluated resource Mcollective::Setting[mcollective::server::setting factsource]: took 0.0011 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.18.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.18 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.yaml]: took 0.0071 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.19.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.19 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcauditprovider]: took 0.0051 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.20.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.20 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcaudit]: took 0.0012 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.21.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.21 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.rpcaudit.logfile]: took 0.0049 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.22.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.22 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcauthorization]: took 0.0011 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.23.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.23 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcauthprovider]: took 0.0038 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.24.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1.24 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.actionpolicy.allow_unconfigured]: took 0.0056 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3.1 Evaluated definitions: took 0.1509 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.3 Iterated (3) on generators: took 0.1510 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.1.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.1 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.host]: took 0.0013 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.2.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.2 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.port]: took 0.0021 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.3.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.3 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.user]: took 0.0052 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.4.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.4 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.password]: took 0.0058 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.5.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.5 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.ssl]: took 0.0012 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.6.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.6 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.ssl.ca]: took 0.0063 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.7.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.7 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.ssl.fallback]: took 0.0044 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.8.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.8 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.activemq.pool.1.ssl.cert]: took 0.0012 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.9.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1.9 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.activemq.pool.1.ssl.key]: took 0.0048 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4.1 Evaluated definitions: took 0.0369 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.4 Iterated (4) on generators: took 0.0394 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.5.1 Evaluated definitions: took 0.0006 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6.5 Iterated (5) on generators: took 0.0007 seconds
Tue Apr 22 13:47:43 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.6 Compile: Evaluated generators: took 4.4055 seconds
Tue Apr 22 13:47:46 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3.7 Compile: Finished catalog: took 2.8447 seconds
Tue Apr 22 13:47:46 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.3 Compiled catalog for bart.rdi-fab.local in environment production: took 18.9744 seconds
Tue Apr 22 13:49:07 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.4 Filtered result for catalog bart.rdi-fab.local: took 23.3341 seconds
Tue Apr 22 13:49:07 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.5 Rendered result in Puppet::Network::Format[pson]: took 0.1286 seconds
Tue Apr 22 13:49:07 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1.6 Sent response: took 0.0001 seconds
Tue Apr 22 13:49:07 +0200 2014 Puppet (debug): PROFILE [70134559059740] 1 Processed request POST /production/catalog/bart.rdi-fab.local: took 102.0031 seconds
-----------------------------------------------------------
-- WITHOUT Directory Environments --
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.1 Found facts: took 0.1326 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.2 Found node information: took 0.3166 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.1 Compile: Set node parameters: took 0.0011 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.2 Compile: Created settings scope: took 0.0044 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.3 Compile: Evaluated main: took 0.0006 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.1 Called realize: took 0.0001 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.1.1 Called template: took 0.0020 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.1 Called include: took 0.0048 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.2.1 Called include: took 0.0079 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.2.2 Called include: took 0.0018 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.2.3 Called include: took 0.0010 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.2.4 Called hiera: took 0.0008 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.2.5 Called create_resources: took 0.0021 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.2 Called include: took 0.0161 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.3.1 Called include: took 0.0012 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.3.2 Called include: took 0.0013 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.3.3 Called include: took 0.0027 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.3 Called include: took 0.0558 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.4 Called include: took 0.0034 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.5.1 Called include: took 0.0015 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.5 Called include: took 0.0029 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.6 Called include: took 0.0011 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.7.1 Called create_resources: took 0.0195 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.7 Called include: took 0.0216 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1.8 Called template: took 0.0013 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2.1 Called include: took 0.1165 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.2 Called include: took 0.1174 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3.1 Called hiera: took 0.0005 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3.2.1 Called template: took 0.0035 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3.2.2 Called template: took 0.0138 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3.2.3 Called template: took 0.0014 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3.2.4 Called template: took 0.0014 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3.2 Called include: took 0.0901 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.3 Called include: took 0.0925 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.1 Called hiera: took 0.0005 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.2 Called hiera: took 0.0005 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.3 Called hiera: took 0.0005 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.4 Called hiera: took 0.0006 seconds
Tue Apr 22 13:56:44 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.5 Called hiera: took 0.0006 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.6 Called include: took 0.3202 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.7 Called file: took 0.0001 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.8 Called defined: took 0.0001 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.9 Called file: took 0.0001 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.10 Called file: took 0.0001 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4.11 Called create_resources: took 0.0019 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.4 Called include: took 0.3332 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4.5 Called include: took 0.0006 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.4 Compile: Evaluated AST node: took 0.5462 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.5 Compile: Evaluated node classes: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.1 Evaluated collections: took 0.0003 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.1 Evaluated resource Environment::Users::Sshuser[cotten]: took 0.0019 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.2 Evaluated resource Environment::Users::Sshuser[volk]: took 0.0019 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.3 Evaluated resource Postfix::File[header_checks]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.4 Evaluated resource Postfix::File[body_checks]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.5 Evaluated resource Postfix::File[canonical_recipient]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.6 Evaluated resource Mcollective::Common::Setting[libdir]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.7 Evaluated resource Mcollective::Common::Setting[connector]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.8 Evaluated resource Mcollective::Common::Setting[securityprovider]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.9 Evaluated resource Mcollective::Common::Setting[collectives]: took 0.0027 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.10 Evaluated resource Mcollective::Common::Setting[main_collective]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.11.1 Called defined: took 0.0028 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.11.2 Called size: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.11.3 Called range: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.11 Evaluated resource Mcollective::Soft_include[::mcollective::common::config::connector::activemq]: took 0.0626 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.12.1 Called defined: took 0.0039 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.12 Evaluated resource Mcollective::Soft_include[::mcollective::common::config::securityprovider::ssl]: took 0.0046 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.13.1 Called template_body: took 0.0002 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.13 Evaluated resource Datacat[mcollective::server]: took 0.0030 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.14 Evaluated resource Mcollective::Server::Setting[classesfile]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.15 Evaluated resource Mcollective::Server::Setting[daemonize]: took 0.0500 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.16 Evaluated resource Mcollective::Server::Setting[logfile]: took 0.0028 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.17 Evaluated resource Mcollective::Server::Setting[loglevel]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.18.1 Called defined: took 0.0029 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.18.2 Called size: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.18.3 Called range: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.18 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::connector::activemq]: took 0.0310 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.19.1 Called defined: took 0.0028 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.19 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::securityprovider::ssl]: took 0.0407 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.20.1 Called defined: took 0.0027 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.20.2 Called template: took 0.0075 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.20 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::factsource::yaml]: took 0.0492 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.21.1 Called defined: took 0.0031 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.21 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::registration::]: took 0.0037 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.22.1 Called defined: took 0.0029 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.22 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::rpcauditprovider::logfile]: took 0.0795 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.23.1 Called defined: took 0.0029 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.23 Evaluated resource Mcollective::Soft_include[::mcollective::server::config::rpcauthprovider::action_policy]: took 0.0389 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.24 Evaluated resource Mcollective::Common::Setting[plugin.activemq.heartbeat_interval]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2.25 Evaluated resource Mcollective::Plugin[misc]: took 0.0028 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1.2 Evaluated definitions: took 0.4006 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.1 Iterated (1) on generators: took 0.4011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.1.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.1 Evaluated resource Mcollective::Setting[mcollective::common::setting libdir]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.2.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.2 Evaluated resource Mcollective::Setting[mcollective::common::setting connector]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.3.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.3 Evaluated resource Mcollective::Setting[mcollective::common::setting securityprovider]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.4.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.4 Evaluated resource Mcollective::Setting[mcollective::common::setting collectives]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.5.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.5 Evaluated resource Mcollective::Setting[mcollective::common::setting main_collective]: took 0.0010 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.6 Evaluated resource Mcollective::Common::Setting[direct_addressing]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.7 Evaluated resource Mcollective::Common::Setting[plugin.activemq.base64]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.8 Evaluated resource Mcollective::Common::Setting[plugin.activemq.randomize]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.9 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.size]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.10 Evaluated resource Mcollective::Common::Config::Connector::Activemq::Hosts_iteration[1]: took 0.1650 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.11.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.11 Evaluated resource Mcollective::Setting[mcollective::server::setting classesfile]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.12.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.12 Evaluated resource Mcollective::Setting[mcollective::server::setting daemonize]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.13.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.13 Evaluated resource Mcollective::Setting[mcollective::server::setting logfile]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.14.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.14 Evaluated resource Mcollective::Setting[mcollective::server::setting loglevel]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.15 Evaluated resource Mcollective::Server::Config::Connector::Activemq::Hosts_iteration[1]: took 0.0274 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.16 Evaluated resource Mcollective::Server::Setting[plugin.ssl_client_cert_dir]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.17 Evaluated resource Mcollective::Server::Setting[plugin.ssl_server_public]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.18 Evaluated resource Mcollective::Server::Setting[plugin.ssl_server_private]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.19 Evaluated resource Mcollective::Server::Setting[factsource]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.20 Evaluated resource Mcollective::Server::Setting[plugin.yaml]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.21 Evaluated resource Mcollective::Server::Setting[rpcauditprovider]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.22 Evaluated resource Mcollective::Server::Setting[rpcaudit]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.23 Evaluated resource Mcollective::Server::Setting[plugin.rpcaudit.logfile]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.24 Evaluated resource Mcollective::Plugin[actionpolicy]: took 0.0028 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.25 Evaluated resource Mcollective::Server::Setting[rpcauthorization]: took 0.0033 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.26 Evaluated resource Mcollective::Server::Setting[rpcauthprovider]: took 0.0027 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.27 Evaluated resource Mcollective::Server::Setting[plugin.actionpolicy.allow_unconfigured]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.28.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1.28 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.heartbeat_interval]: took 0.0010 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2.1 Evaluated definitions: took 0.2506 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.2 Iterated (2) on generators: took 0.2507 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.1.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.1 Evaluated resource Mcollective::Setting[mcollective::common::setting direct_addressing]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.2.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.2 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.base64]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.3.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.3 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.randomize]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.4.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.4 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.size]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.5 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.host]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.6 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.port]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.7 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.user]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.8 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.password]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.9 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.ssl]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.10 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.ssl.ca]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.11 Evaluated resource Mcollective::Common::Setting[plugin.activemq.pool.1.ssl.fallback]: took 0.0025 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.12 Evaluated resource Mcollective::Server::Setting[plugin.activemq.pool.1.ssl.cert]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.13 Evaluated resource Mcollective::Server::Setting[plugin.activemq.pool.1.ssl.key]: took 0.0026 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.14.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.14 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.ssl_client_cert_dir]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.15.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.15 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.ssl_server_public]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.16.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.16 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.ssl_server_private]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.17.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.17 Evaluated resource Mcollective::Setting[mcollective::server::setting factsource]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.18.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.18 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.yaml]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.19.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.19 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcauditprovider]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.20.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.20 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcaudit]: took 0.0506 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.21.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.21 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.rpcaudit.logfile]: took 0.0013 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.22.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.22 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcauthorization]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.23.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.23 Evaluated resource Mcollective::Setting[mcollective::server::setting rpcauthprovider]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.24.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1.24 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.actionpolicy.allow_unconfigured]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3.1 Evaluated definitions: took 0.0943 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.3 Iterated (3) on generators: took 0.0944 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.1.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.1 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.host]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.2.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.2 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.port]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.3.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.3 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.user]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.4.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.4 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.password]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.5.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.5 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.ssl]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.6.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.6 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.ssl.ca]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.7.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.7 Evaluated resource Mcollective::Setting[mcollective::common::setting plugin.activemq.pool.1.ssl.fallback]: took 0.0012 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.8.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.8 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.activemq.pool.1.ssl.cert]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.9.1 Called hash: took 0.0000 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1.9 Evaluated resource Mcollective::Setting[mcollective::server::setting plugin.activemq.pool.1.ssl.key]: took 0.0011 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4.1 Evaluated definitions: took 0.0121 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.4 Iterated (4) on generators: took 0.0122 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.5.1 Evaluated definitions: took 0.0005 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6.5 Iterated (5) on generators: took 0.0007 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.6 Compile: Evaluated generators: took 0.7598 seconds
Tue Apr 22 13:56:45 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3.7 Compile: Finished catalog: took 0.0260 seconds
Tue Apr 22 13:56:46 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.3 Compiled catalog for bart.rdi-fab.local in environment production: took 1.4108 seconds
Tue Apr 22 13:56:47 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.4 Filtered result for catalog bart.rdi-fab.local: took 0.1641 seconds
Tue Apr 22 13:56:47 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.5 Rendered result in Puppet::Network::Format[pson]: took 0.0618 seconds
Tue Apr 22 13:56:47 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1.6 Sent response: took 0.0001 seconds
Tue Apr 22 13:56:47 +0200 2014 Puppet (debug): PROFILE [70193344605340] 1 Processed request POST /production/catalog/bart.rdi-fab.local: took 3.0145 seconds
-----------------------------------------------------------


This is what the load average and Passenger status look like with 1 and 3 simultaneous Puppet runs:

-- 1 run --

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 1085 puppet    20   0  250m 148m 3232 R 92.8  5.1   0:03.91 Passenger RackApp: /etc/puppet/rack

----------- General information -----------
Max pool size : 12
Processes     : 2
Requests in top-level queue : 0

----------- Application groups -----------
/etc/puppet/rack#default:
  App root: /etc/puppet/rack
  Requests in queue: 0
  * PID: 1085    Sessions: 0       Processed: 4       Uptime: 49s
    CPU: 59%     Memory  : 127M    Last used: 33s ago
  

-- 3 runs --

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 1085 puppet    20   0  262m 160m 3304 R 34.1  5.6   0:48.24 Passenger RackApp: /etc/puppet/rack
 1329 puppet    20   0  258m 156m 3240 R 32.5  5.4   0:16.16 Passenger RackApp: /etc/puppet/rack
 1340 puppet    20   0  260m 158m 3248 R 32.5  5.5   0:14.94 Passenger RackApp: /etc/puppet/rack


----------- General information -----------
Max pool size : 12
Processes     : 4
Requests in top-level queue : 0

----------- Application groups -----------
/etc/puppet/rack#default:
  App root: /etc/puppet/rack
  Requests in queue: 0
  * PID: 1085    Sessions: 1       Processed: 22      Uptime: 2m 40s
    CPU: 25%     Memory  : 128M    Last used: 30s ago
  * PID: 1329    Sessions: 1       Processed: 1       Uptime: 29s
    CPU: 28%     Memory  : 124M    Last used: 29s ago
  * PID: 1340    Sessions: 1       Processed: 2       Uptime: 28s
    CPU: 25%     Memory  : 123M    Last used: 26s ago



Can't believe I am the only one in this situation. Am I?
Thank you in advance advance for the feedback.

Toni

[Niels Abspoel]

I can confirm this, and reproduce:

running centos 6.5 master with apache passenger.

if I disable:

[production]

manifest = /etc/puppet/environments/production/manifests/site.pp

modulepath = /etc/puppet/environments/production/modules

and add 

 [main]

environmentpath = $confdir/environments

I get the following error message:

Could not retrieve catalog from remote server: execution expired

total nodes: 150 in production environment.

Puppet master goes to 100% per thread.

If I revert the change, everything goes back to normal.

and the catalog time is 15.52 seconds.

With regards

Niels

Op donderdag 17 april 2014 11:23:24 UTC+2 schreef Antoine Cotten:

[Eric Sorenson]

On Tuesday, April 22, 2014 5:25:55 AM UTC-7, Antoine Cotten wrote:

Hi Eric,
thank you for pointing me to this feature, and sorry for the answer time.

I managed to outline the problematic parts in the Puppet run: the final POST method takes forever when Directory Environments is enabled (1) and the catalog compilation is overall much slower (1.3./4|5|6/)

I triggered a run on the same node, with and without the feature enabled. Here are the corresponding profiling logs:

Thanks, this is great information.

The reason the POST looks slow is because it's an aggregate of all the steps that came before it, as you see the profile step numbers pop out a level, that line aggregates the times of everything inside it.  So the POST is the aggregate of all the steps to compilation.

I am looking at this more closely and I have opened https://tickets.puppetlabs.com/browse/PUP-2337 to track it.

--eric0

[Josh Partlow]

Hi Antoine,

There is a Puppet 3.6.0-rc1 available in the pre-release repos which has environment cacheing that we think will take care of the slowdown you are seeing with directory environments.  Would you be able to test that?  (See Eric's 3.6.0-rc1 announcement for details on obtaining the packages)

thanks,

Josh

[Antoine Cotten]

Thanks Josh,

This seems to work better indeed, although I can still observe a decrease in performances. The config retrieval time is higher than with config-based environments (9 sec -> 26 sec on average), and CPU-wise I can also notice an increase but this is hard to quantify without prolonged monitoring, I'll let it run for 24 extra hours before giving any conclusion. But, well, nothing compared to v3.5.1 fortunately, so I believe this RC1 is promising!

Feel free to ask if you need any data or extra feedback from me.

--
Toni

[Joshua Partlow]

On Wed, May 7, 2014 at 6:24 AM, Antoine Cotten <tonio....@gmail.com> wrote:

Thanks Josh,

This seems to work better indeed, although I can still observe a decrease in performances. The config retrieval time is higher than with config-based environments (9 sec -> 26 sec on average), and CPU-wise I can also notice an increase but this is hard to quantify without prolonged monitoring, I'll let it run for 24 extra hours before giving any conclusion. But, well, nothing compared to v3.5.1 fortunately, so I believe this RC1 is promising!

Feel free to ask if you need any data or extra feedback from me.

Thanks for testing this, Antoine!  There is a time to live setting for the new environment cache which defaults to 5 seconds.  It's 'environment_timeout' and you can set it in your puppet.conf, or per directory environment in it's environment.conf.  I'm curious what, if any, change you see setting it to say '30s', and what change if you set it 'unlimited'.

Would you have time to test that?

thanks,

Josh

 

--
Toni

On Tuesday, May 6, 2014 10:55:24 PM UTC+2, Josh Partlow wrote:

Hi Antoine,

There is a Puppet 3.6.0-rc1 available in the pre-release repos which has environment cacheing that we think will take care of the slowdown you are seeing with directory environments.  Would you be able to test that?  (See Eric's 3.6.0-rc1 announcement for details on obtaining the packages)

thanks,

Josh

On Tuesday, April 22, 2014 11:26:47 AM UTC-7, Eric Sorenson wrote:

On Tuesday, April 22, 2014 5:25:55 AM UTC-7, Antoine Cotten wrote:

Hi Eric,
thank you for pointing me to this feature, and sorry for the answer time.

I managed to outline the problematic parts in the Puppet run: the final POST method takes forever when Directory Environments is enabled (1) and the catalog compilation is overall much slower (1.3./4|5|6/)

I triggered a run on the same node, with and without the feature enabled. Here are the corresponding profiling logs:

Thanks, this is great information.

The reason the POST looks slow is because it's an aggregate of all the steps that came before it, as you see the profile step numbers pop out a level, that line aggregates the times of everything inside it.  So the POST is the aggregate of all the steps to compilation.

I am looking at this more closely and I have opened https://tickets.puppetlabs.com/browse/PUP-2337 to track it.

--eric0

--
You received this message because you are subscribed to a topic in the Google Groups "Puppet Users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/puppet-users/wzy8NPWauu4/unsubscribe.
To unsubscribe from this group and all its topics, send an email to puppet-users...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/0008dd5d-fab6-4d01-b206-6a1994236b42%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Josh Partlow

jpar...@puppetlabs.com

Developer, Puppet Labs

Join us at PuppetConf 2014, September 22-24 in San Francisco - http://puppetconf.com

Register by May 30th to take advantage of the Early Adopter discount —save $349!

[Antoine Cotten]

Hi Josh,

I will test it today and tell you what I observe.

Regarding performances:

• the increase in CPU consumption is hard to quantify precisely. I can only tell the load average changed from ~0.30-0.60 to ~1.00-1.50 with regular peaks up to 2.50. Nagios even reported 15.0 a couple of times in the past 2 days.
  
• it uses a lot more memory. Before my memory consumption was constantly around 60% of 3GB, now it oscillates around 90% and my master swaps a lot. Nagios gets quite crazy about it.

To be continued...

[Antoine Cotten]

Hi Josh, hi all,

So, I have set the environment_timeout setting to a couple of test values, including 30s, 1h and unlimited:

• 30s - No performance boost. Too short for me, my Puppet runs are distributed every 37s
  
• 1h - Very good results, fast config retrieval, even slighly better than with config-based environments
  
• unlimited - same as above
  

Regarding performance issues please ignore my previous message, I had some other troubles in my vSphere environment which caused these CPU and memory peaks. My Puppet master behaves in a very stable way now.

Cheers,

--
Toni

[Joshua Partlow]

That's great to hear; thank you for testing that Antoine!

- Josh

--

You received this message because you are subscribed to a topic in the Google Groups "Puppet Users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/puppet-users/wzy8NPWauu4/unsubscribe.
To unsubscribe from this group and all its topics, send an email to puppet-users...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/7ed02dd8-8dfe-4ea2-bcc1-d864132aa761%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Kirk Steffensen]

Running in webrick, for the exact same node, we saw 458 seconds to compile using directory environments vs 4.5 seconds using the old file-based environments.

[Eric Sorenson]

On May 14, 2014, at 12:28 PM, Kirk Steffensen <ki...@steffensenfamily.com> wrote:

> Running in webrick, for the exact same node, we saw 458 seconds to compile using directory environments vs 4.5 seconds using the old file-based environments.

Kirk, did you try this in 3.6.0-RC1? Later in this thread Antoine reported his slowdown was fixed and I’m wondering if you see the same thing.

Eric Sorenson - eric.s...@puppetlabs.com - freenode #puppet: eric0
puppet platform // coffee // techno // bicycles

[Chuck]

I had to set environment_timeout to at least 60 seconds.  The default was causing cpu / memory issues on my puppet master.  I am still tuning it at this time.

[Chuck]

After a few more hours I am still seeing the high memory usage no matter what I set the environment_timeout to.