Jira (PUP-5217) compile profiler metrics are incorrect

Justin Stoller (JIRA) Thu, 15 Mar 2018 14:24:57 -0700

Title: Message Title

Here is a catalog request, with a trivial catalog, when running Puppet Server from the repl with a puppet.conf that includes profile = "" 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 ----------------------------

Add Comment

This message was sent by Atlassian JIRA

--
You received this message because you are subscribed to the Google Groups "Puppet Bugs" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
To post to this group, send email to [email protected].
Visit this group at https://groups.google.com/group/puppet-bugs.
For more options, visit https://groups.google.com/d/optout.

Jira (PUP-5217) compile profiler metrics are incorrect

Reply via email to