Details
-
Bug
-
Status: Closed
-
Normal
-
Resolution: Fixed
-
None
-
None
-
None
-
-
Coremunity
-
Platform Core KANBAN
-
Customer Feedback
-
Reviewed
-
Bug Fix
-
Total time now reports the measured time of the run instead of a sum of other run times.
Description
The time reported by a `puppet agent -t` run for "Applied catalog in" does not appear to correlate to the times reported in the Puppet::Util::Metric "time" array. The applied catalog time should be the time used to apply the resources in the catalog, and the times returned to the report processor in the Puppet::Util::Metric "time" array should be the amount of time spent applying each resource, yet the two do not add up. Sometimes the applied catalog line is larger and sometimes the total time is larger.
# cat lib/puppet/reports/myreport.rb
|
require 'puppet' |
Puppet::Reports.register_report(:myreport) do |
desc "Testing" |
|
|
def process
|
Puppet.notice "METRICS: Process Puppet Report" |
Puppet.notice "METRICS: self.logs.last.message: #{self.logs.last.message}" |
self.metrics['time'].values.each { |val| |
Puppet.notice "METRICS: #{val[1]} : #{val[2]}" |
}
|
end
|
# puppet agent -t
|
Info: Using configured environment 'production' |
Info: Retrieving pluginfacts
|
Info: Retrieving plugin
|
Info: Loading facts
|
Info: Caching catalog for pe-201612-master.puppetdebug.vlan |
Info: Applying configuration version '1464042693' |
Notice: Applied catalog in 9.18 seconds |
# tail -n 21 /var/log/puppetlabs/puppetserver/puppetserver.log |
2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Process Puppet Report |
2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: self.logs.last.message: Applied catalog in 9.18 seconds |
2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Augeas : 1.017779943 |
2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Config retrieval : 10.645895659 |
2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Cron : 0.001115222 |
2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Exec : 0.169413854 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: File : 0.45819617799999984 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Filebucket : 0.000103239 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Group : 0.000411452 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Package : 0.7939065209999999 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe anchor : 7.1151e-05 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe file line : 0.0023166209999999996 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe hocon setting : 1.4407772629999998 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe ini setting : 0.020410037 |
2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe ini subsetting : 0.0049442060000000005 |
2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe java ks : 1.454764838 |
2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe puppet authorization hocon rule : 1.8567533360000004 |
2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Schedule : 0.00041616200000000003 |
2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Service : 0.35225476499999997 |
2016-05-23 22:31:53,923 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Total : 18.221604979000002 |
2016-05-23 22:31:53,923 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: User : 0.002074532 |
In this case, the catalog applied in 9.18 seconds, but the (Total) - (Config retrieval) is 7.57 even though the documentation would seem to indicate they are measuring the same thing.
