Jira (PUP-5217) compile profiler metrics are incorrect

9 views
Skip to first unread message

Josh Cooper (JIRA)

unread,
Sep 9, 2015, 7:15:02 PM9/9/15
to puppe...@googlegroups.com
Josh Cooper created an issue
 
Puppet / Bug PUP-5217
compile profiler metrics are incorrect
Issue Type: Bug Bug
Affects Versions: PUP 4.2.1
Assignee: Unassigned
Created: 2015/09/09 4:14 PM
Priority: Normal Normal
Reporter: Josh Cooper

While reviewing PUP-5013, I found that if the compiler spends N seconds evaluating a resource (in the examples below N is 3), then in 4.2.1 with an ENC the profiler will report the compiler took 5N seconds:

Debug: compiler: 15.775227 s (16 calls)
 
Debug: compiler -> compile: 3.339482 s (1 calls)
 
...
 
Debug: compiler -> evaluate_resource: 3.027471 s (1 calls)

and if not using an ENC, will report 2N seconds (note due to PUP-5013 the profile doesn't specify the evaluate_resource times):

Debug: compiler: 6.399003 s (13 calls)
 
Debug: compiler -> compile: 3.335047 s (1 calls)

With PUP-5013 fixed, it reports a similarly inflated times with an ENC (5x the total evaluate_resource time):

Debug: compiler: 15.782144999999998 s (17 calls)
 
Debug: compiler -> compile: 3.338612 s (1 calls)
 
...
 
Debug: compiler -> evaluate_resource: 3.027264 s (2 calls)

And without (2x the total evaluate_resource time, which is itself already double counted):

Debug: compiler: 12.440194 s (16 calls)
 
Debug: compiler -> evaluate_resource: 6.0394250000000005 s (3 calls)
 
...
 
Debug: compiler -> compile: 3.338293 s (1 calls)

If I change N to be 10, then the compiler times increase proportionally, so it's clear the times are being over counted.

To reproduce (without an ENC), create a manifest in $codedir/environments/production/manifests/site.pp:

class common {
 
  notify { 'test':
 
    message => generate("/path/to/exec_sleep.sh"),
 
  }
 
}
 
 
 
node default {
 
  include common
 
}

where exec_sleep.sh is executable and does:

#!/bin/bash
 
sleep 3

Start the master, run an agent, and if using 4.2.2, you'll see something like:

# puppet master --no-daemonize --debug --profile
 
...
 
Debug: compiler: 12.440194 s (16 calls)
 
Debug: compiler -> evaluate_resource: 6.0394250000000005 s (3 calls)
 
Debug: compiler -> evaluate_resource -> Node[default]: 3.020519 s (1 calls)
 
Debug: compiler -> evaluate_resource -> Class[Common]: 3.017993 s (1 calls)
 
Debug: compiler -> evaluate_resource -> Class[main]: 0.000913 s (1 calls)
 
Debug: compiler -> compile: 3.338293 s (1 calls)
 
Debug: compiler -> compile -> production: 3.338293 s (1 calls)
 
Debug: compiler -> compile -> production -> arcturus.delivery.puppetlabs.net: 3.338293 s (1 calls)
 
Debug: compiler -> evaluate_ast_node: 3.020912 s (1 calls)
 
Debug: compiler -> init_server_facts: 0.012254 s (1 calls)
 
Debug: compiler -> find_node: 0.011465 s (1 calls)
 
Debug: compiler -> find_facts: 0.010875 s (1 calls)
 
Debug: compiler -> create_settings_scope: 0.004478 s (1 calls)
 
Debug: compiler -> evaluate_main: 0.001096 s (1 calls)
 
Debug: compiler -> set_node_params: 0.000706 s (1 calls)
 
Debug: compiler -> finish_catalog: 0.000263 s (1 calls)
 
Debug: compiler -> evaluate_generators: 0.000254 s (1 calls)
 
Debug: compiler -> iterate_on_generators: 0.000132 s (1 calls)
 
Debug: compiler -> evaluate_node_classes: 2.6e-05 s (1 calls)
 
Debug: compiler -> evaluate_definitions: 1.5e-05 s (1 calls)

It appears the Node[default] and Class[Common] times are added together rather than recognizing that the time spent in the former includes the time spent in the latter.

Similar things happen when using an ENC (except it's 5x the evaluate_resource time):

Debug: compiler: 15.775227 s (16 calls)
 
Debug: compiler -> compile: 3.339482 s (1 calls)
 
Debug: compiler -> compile -> production: 3.339482 s (1 calls)
 
Debug: compiler -> compile -> production -> arcturus.delivery.puppetlabs.net: 3.339482 s (1 calls)
 
Debug: compiler -> evaluate_generators: 3.028134 s (1 calls)
 
Debug: compiler -> iterate_on_generators: 3.0278989999999997 s (2 calls)
 
Debug: compiler -> evaluate_definitions: 3.027682 s (2 calls)
 
Debug: compiler -> evaluate_resource: 3.027471 s (1 calls)
 
Debug: compiler -> evaluate_resource -> Class[Common]: 3.027471 s (1 calls)
 
Debug: compiler -> find_node: 0.294042 s (1 calls)
 
Debug: compiler -> init_server_facts: 0.012917 s (1 calls)
 
Debug: compiler -> find_facts: 0.010516 s (1 calls)
 
Debug: compiler -> create_settings_scope: 0.004485 s (1 calls)
 
Debug: compiler -> evaluate_main: 0.001235 s (1 calls)
 
Debug: compiler -> set_node_params: 0.000984 s (1 calls)
 
Debug: compiler -> finish_catalog: 0.000205 s (1 calls)
 
Debug: compiler -> evaluate_node_classes: 0.000163 s (1 calls)
 
Debug: compiler -> evaluate_ast_node: 1.2e-05 s (1 calls)

Add Comment Add Comment
 
This message was sent by Atlassian JIRA (v6.4.11#64026-sha1:78f6ec4)
Atlassian logo

Josh Cooper (JIRA)

unread,
Apr 22, 2016, 3:15:02 AM4/22/16
to puppe...@googlegroups.com
Josh Cooper commented on Bug PUP-5217
 
Re: compile profiler metrics are incorrect

Chris Price, Kylo Ginsberg, Henrik Lindberg not sure who wants this one, but since PE ships with an ENC, it seems like it'd be good to get this straightened out.
This message was sent by Atlassian JIRA (v6.4.13#64028-sha1:b7939e9)
Atlassian logo

Henrik Lindberg (JIRA)

unread,
Apr 22, 2016, 12:03:49 PM4/22/16
to puppe...@googlegroups.com

I wonder if measurements were correct before switching to new Profiler (commits references in

PUP-5013 ) and if PUP-5013 got it wrong when using the new Profiler (i.e. missing to make calls to form the hierarchy of measurements).

Chris Price (JIRA)

unread,
Apr 27, 2016, 8:56:03 PM4/27/16
to puppe...@googlegroups.com
Chris Price commented on Bug PUP-5217

I don't think the profiler code that is generating these numbers is even used when running in Puppet Server, so if we're going to put any effort into this it'd probably be good to see what the numbers look like when running with the profiler that is used in Puppet Server.

Branan Riley (JIRA)

unread,
May 15, 2017, 4:28:04 PM5/15/17
to puppe...@googlegroups.com
Branan Riley updated an issue
 
Change By: Branan Riley
Story Points: 3
This message was sent by Atlassian JIRA (v6.4.14#64029-sha1:ae256fe)
Atlassian logo

Branan Riley (JIRA)

unread,
May 15, 2017, 4:28:04 PM5/15/17
to puppe...@googlegroups.com
Branan Riley updated an issue
Change By: Branan Riley
Labels: triaged

Branan Riley (JIRA)

unread,
May 15, 2017, 4:28:04 PM5/15/17
to puppe...@googlegroups.com
Branan Riley updated an issue
Change By: Branan Riley
Team: Agent

Josh Cooper (JIRA)

unread,
Mar 15, 2018, 12:32:03 PM3/15/18
to puppe...@googlegroups.com
This message was sent by Atlassian JIRA (v7.7.1#77002-sha1:e75ca93)
Atlassian logo

Charlie Sharpsteen (JIRA)

unread,
Mar 15, 2018, 1:09:03 PM3/15/18
to puppe...@googlegroups.com

Huh. Interesting. Does the experiment produce the same results with recent puppet server versions?

Justin Stoller (JIRA)

unread,
Mar 15, 2018, 5:24:32 PM3/15/18
to puppe...@googlegroups.com

Here is a catalog request, with a trivial catalog, when running Puppet Server from the repl with a puppet.conf that includes profile = true in the master section:

2018-03-15 14:17:28,401 INFO  [qtp1109725453-32] [puppetserver] Puppet ----------------------------
 
2018-03-15 14:17:31,591 DEBUG [qtp1109725453-32] [p.r.core] Processing :post /puppet/v3/catalog/localhost
 
2018-03-15 14:17:31,599 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
 
2018-03-15 14:17:31,599 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evaluating match for Route /v3/
 
2018-03-15 14:17:31,599 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
 
2018-03-15 14:17:31,599 DEBUG [qtp1109725453-32] [puppetserver] Puppet Did not match path ("/catalog/localhost")
 
2018-03-15 14:17:31,600 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evaluating match for Route /^\/environment\/[^\/]+$/
 
2018-03-15 14:17:31,600 DEBUG [qtp1109725453-32] [puppetserver] Puppet Did not match path ("/catalog/localhost")
 
2018-03-15 14:17:31,600 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evaluating match for Route /.*/
 
2018-03-15 14:17:31,600 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:31,600 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:31,602 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:31,602 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:31,603 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:31,603 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:31,605 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:31,605 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:31,658 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.1 Setup server facts for compiling: took 0.0430 seconds
 
2018-03-15 14:17:31,682 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.2 Found facts: took 0.0220 seconds
 
2018-03-15 14:17:31,728 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.3 Found node information: took 0.0010 seconds
 
2018-03-15 14:17:31,782 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.1 Compile: Set node parameters: took 0.0010 seconds
 
2018-03-15 14:17:31,791 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.2 Compile: Created settings scope: took 0.0090 seconds
 
2018-03-15 14:17:31,791 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.3 Compile: Evaluated capability mappings: took 0.0000 seconds
 
2018-03-15 14:17:31,793 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.4.1 Evaluated resource Class[main]: took 0.0010 seconds
 
2018-03-15 14:17:31,794 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.4 Compile: Evaluated main: took 0.0030 seconds
 
2018-03-15 14:17:31,795 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.5 Compile: Evaluated site: took 0.0000 seconds
 
2018-03-15 14:17:31,815 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1.1 Called capitalize: took 0.0010 seconds
 
2018-03-15 14:17:31,817 INFO  [qtp1109725453-32] [puppetserver] Scope(Node[default])
 
2018-03-15 14:17:31,818 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1.2 info: took 0.0000 seconds
 
2018-03-15 14:17:31,819 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1.3 Called capitalize: took 0.0000 seconds
 
2018-03-15 14:17:31,819 INFO  [qtp1109725453-32] [puppetserver] Scope(Node[default])
 
2018-03-15 14:17:31,820 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1.4 info: took 0.0010 seconds
 
2018-03-15 14:17:31,821 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1.5 Called capitalize: took 0.0000 seconds
 
2018-03-15 14:17:31,822 INFO  [qtp1109725453-32] [puppetserver] Scope(Node[default])
 
2018-03-15 14:17:31,822 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1.6 info: took 0.0010 seconds
 
2018-03-15 14:17:31,822 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.1 map: took 0.0150 seconds
 
2018-03-15 14:17:31,836 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.2 each: took 0.0080 seconds
 
2018-03-15 14:17:31,882 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:31,882 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:31,887 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:31,888 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:31,902 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:31,902 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:31,905 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:31,905 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:31,907 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:31,908 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:31,911 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:31,911 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:32,047 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:32,047 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:32,051 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:32,051 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:32,056 DEBUG [qtp1109725453-32] [puppetserver] Puppet Reloading pip package provider
 
2018-03-15 14:17:32,059 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:32,059 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:32,062 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:32,062 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:32,064 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:32,064 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:32,068 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:32,068 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:32,143 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:32,144 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:32,149 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:32,149 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:32,152 DEBUG [qtp1109725453-32] [puppetserver] Puppet Evicting cache entry for environment 'production'
 
2018-03-15 14:17:32,152 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Removing environment 'production' from registry
 
2018-03-15 14:17:32,157 DEBUG [qtp1109725453-32] [p.s.j.puppet-environments] Registering environment 'production'
 
2018-03-15 14:17:32,157 DEBUG [qtp1109725453-32] [puppetserver] Puppet Caching environment 'production' (ttl = 0 sec)
 
2018-03-15 14:17:32,241 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.3 each: took 0.4040 seconds
 
2018-03-15 14:17:32,250 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1.4 each: took 0.0090 seconds
 
2018-03-15 14:17:32,251 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6.1 Evaluated resource Node[default]: took 0.4560 seconds
 
2018-03-15 14:17:32,252 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.6 Compile: Evaluated AST node: took 0.4560 seconds
 
2018-03-15 14:17:32,252 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.7 Compile: Evaluated node classes: took 0.0000 seconds
 
2018-03-15 14:17:32,253 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.8 Compile: Evaluated application instances: took 0.0000 seconds
 
2018-03-15 14:17:32,253 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.9 Compile: Evaluated site capability mappings: took 0.0000 seconds
 
2018-03-15 14:17:32,254 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.10.1.1 Evaluated definitions: took 0.0010 seconds
 
2018-03-15 14:17:32,254 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.10.1 Iterated (1) on generators: took 0.0010 seconds
 
2018-03-15 14:17:32,255 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.10 Compile: Evaluated generators: took 0.0020 seconds
 
2018-03-15 14:17:32,256 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.11 Compile: Validate Catalog pre-finish: took 0.0010 seconds
 
2018-03-15 14:17:32,257 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.12 Compile: Finished catalog: took 0.0010 seconds
 
2018-03-15 14:17:32,258 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.13 Compile: Prune: took 0.0010 seconds
 
2018-03-15 14:17:32,258 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4.14 Compile: Validate Catalog final: took 0.0000 seconds
 
2018-03-15 14:17:32,262 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.4 Compiled catalog for localhost in environment production: took 0.5220 seconds
 
2018-03-15 14:17:32,262 INFO  [qtp1109725453-32] [puppetserver] Puppet Compiled catalog for localhost in environment production in 0.52 seconds
 
2018-03-15 14:17:32,265 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.5 Filtered result for catalog localhost: took 0.0030 seconds
 
2018-03-15 14:17:32,265 DEBUG [qtp1109725453-32] [puppetserver] Puppet Puppet::Network::Format[msgpack]: feature msgpack is missing
 
2018-03-15 14:17:32,265 DEBUG [qtp1109725453-32] [puppetserver] Puppet catalog supports formats: json pson yaml dot
 
2018-03-15 14:17:32,270 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.6 Rendered result in Puppet::Network::Format[json]: took 0.0040 seconds
 
2018-03-15 14:17:32,270 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1.7 Sent response: took 0.0000 seconds
 
2018-03-15 14:17:32,270 INFO  [qtp1109725453-32] [puppetserver] Puppet PROFILE [8742] 1 Processed request POST /puppet/v3/catalog/localhost: took 0.6710 seconds
 
2018-03-15 14:17:32,270 INFO  [qtp1109725453-32] [puppetserver] Puppet AGGREGATE PROFILING RESULTS:
 
2018-03-15 14:17:32,271 INFO  [qtp1109725453-32] [puppetserver] Puppet ----------------------------
 
2018-03-15 14:17:32,271 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler: 1.521 s (22 calls)
 
2018-03-15 14:17:32,271 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> compile: 0.522 s (1 calls)
 
2018-03-15 14:17:32,271 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> compile -> production: 0.522 s (1 calls)
 
2018-03-15 14:17:32,271 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> compile -> production -> localhost: 0.522 s (1 calls)
 
2018-03-15 14:17:32,272 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_resource: 0.457 s (2 calls)
 
2018-03-15 14:17:32,272 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_resource -> Node[default]: 0.456 s (1 calls)
 
2018-03-15 14:17:32,272 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_resource -> Class[main]: 0.001 s (1 calls)
 
2018-03-15 14:17:32,272 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_ast_node: 0.456 s (1 calls)
 
2018-03-15 14:17:32,272 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> init_server_facts: 0.043 s (1 calls)
 
2018-03-15 14:17:32,273 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> find_facts: 0.022 s (1 calls)
 
2018-03-15 14:17:32,273 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> create_settings_scope: 0.009 s (1 calls)
 
2018-03-15 14:17:32,273 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_main: 0.003 s (1 calls)
 
2018-03-15 14:17:32,273 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_generators: 0.002 s (1 calls)
 
2018-03-15 14:17:32,273 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> prune_catalog: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> finish_catalog: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> validate_pre_finish: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> iterate_on_generators: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_definitions: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> set_node_params: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> find_node: 0.001 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> validate_final: 0.0 s (1 calls)
 
2018-03-15 14:17:32,274 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_applications: 0.0 s (1 calls)
 
2018-03-15 14:17:32,275 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_node_classes: 0.0 s (1 calls)
 
2018-03-15 14:17:32,275 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_site: 0.0 s (1 calls)
 
2018-03-15 14:17:32,275 INFO  [qtp1109725453-32] [puppetserver] Puppet compiler -> evaluate_capability_mappings: 0.0 s (2 calls)
 
2018-03-15 14:17:32,275 INFO  [qtp1109725453-32] [puppetserver] Puppet http: 0.675 s (3 calls)
 
2018-03-15 14:17:32,275 INFO  [qtp1109725453-32] [puppetserver] Puppet http -> POST: 0.671 s (1 calls)
 
2018-03-15 14:17:32,276 INFO  [qtp1109725453-32] [puppetserver] Puppet http -> POST -> /puppet/v3/catalog/localhost: 0.671 s (1 calls)
 
2018-03-15 14:17:32,276 INFO  [qtp1109725453-32] [puppetserver] Puppet http -> v3_render: 0.004 s (1 calls)
 
2018-03-15 14:17:32,276 INFO  [qtp1109725453-32] [puppetserver] Puppet http -> v3_render -> Puppet::Network::Format[json]: 0.004 s (1 calls)
 
2018-03-15 14:17:32,276 INFO  [qtp1109725453-32] [puppetserver] Puppet http -> v3_response: 0.0 s (1 calls)
 
2018-03-15 14:17:32,276 INFO  [qtp1109725453-32] [puppetserver] Puppet functions: 0.43900000000000006 s (10 calls)
 
2018-03-15 14:17:32,277 INFO  [qtp1109725453-32] [puppetserver] Puppet functions -> each: 0.42100000000000004 s (3 calls)
 
2018-03-15 14:17:32,277 INFO  [qtp1109725453-32] [puppetserver] Puppet functions -> map: 0.015 s (1 calls)
 
2018-03-15 14:17:32,277 INFO  [qtp1109725453-32] [puppetserver] Puppet functions -> info: 0.002 s (3 calls)
 
2018-03-15 14:17:32,277 INFO  [qtp1109725453-32] [puppetserver] Puppet functions -> capitalize: 0.001 s (3 calls)
 
2018-03-15 14:17:32,278 INFO  [qtp1109725453-32] [puppetserver] Puppet indirector: 0.003 s (1 calls)
 
2018-03-15 14:17:32,278 INFO  [qtp1109725453-32] [puppetserver] Puppet indirector -> filter: 0.003 s (1 calls)
 
2018-03-15 14:17:32,278 INFO  [qtp1109725453-32] [puppetserver] Puppet indirector -> filter -> catalog: 0.003 s (1 calls)
 
2018-03-15 14:17:32,278 INFO  [qtp1109725453-32] [puppetserver] Puppet indirector -> filter -> catalog -> localhost: 0.003 s (1 calls)
 
2018-03-15 14:17:32,278 INFO  [qtp1109725453-32] [puppetserver] Puppet ----------------------------

Josh Cooper (JIRA)

unread,
Mar 15, 2018, 6:22:04 PM3/15/18
to puppe...@googlegroups.com
Josh Cooper commented on Bug PUP-5217

Yeah, it looks like the top-level evaluate_resource metric adds Node and Class times (so N*2), and the overall compilation time is N*4

Josh Cooper (JIRA)

unread,
Mar 15, 2018, 6:22:06 PM3/15/18
to puppe...@googlegroups.com
Josh Cooper updated an issue
 
Change By: Josh Cooper
Sub-team: Server

Charlie Sharpsteen (JIRA)

unread,
Mar 15, 2018, 9:27:02 PM3/15/18
to puppe...@googlegroups.com
Charlie Sharpsteen commented on Bug PUP-5217
 
Re: compile profiler metrics are incorrect

If Puppet::Util::Profiler::Aggregate is just summing all the times recorded by all calls to Puppet::Util::Profiler.profile, then this looks like an expected result. The times recorded by Puppet::Util::Profiler.profile blocks are inclusive of any Puppet::Util::Profiler.profile blocks that may be nested, so things get double counted.

I had to sort this out when updating Finch's puppet-profile-parser, here's the ticket for that:

https://github.com/Sharpie/puppet-profile-parser/issues/1

David McTavish (Jira)

unread,
Dec 1, 2021, 11:28:02 AM12/1/21
to puppe...@googlegroups.com
David McTavish updated an issue
 
Change By: David McTavish
Labels: final_triage
This message was sent by Atlassian Jira (v8.13.2#813002-sha1:c495a97)
Atlassian logo

Josh Cooper (Jira)

unread,
Dec 3, 2021, 11:26:03 AM12/3/21
to puppe...@googlegroups.com
Josh Cooper updated an issue
Change By: Josh Cooper
Team: Froyo

Molly Waggett (Jira)

unread,
Feb 22, 2022, 1:36:02 PM2/22/22
to puppe...@googlegroups.com
Molly Waggett updated an issue
Change By: Molly Waggett
Labels: final_triage
This message was sent by Atlassian Jira (v8.20.2#820002-sha1:829506d)
Atlassian logo

David McTavish (Jira)

unread,
Mar 8, 2022, 11:48:02 AM3/8/22
to puppe...@googlegroups.com
David McTavish updated an issue
Change By: David McTavish
Epic Link: SERVER-792
Reply all
Reply to author
Forward
0 new messages