Uploaded image for project: 'Puppet'
  1. Puppet
  2. PUP-6344

metrics.time.total does not correlate to time reported in log

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Normal
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: PUP 5.5.1, PUP 6.0.0
    • Component/s: None
    • Labels:
      None
    • Template:
    • Acceptance Criteria:
      Hide

      The total time should represent the amount of time spent by the agent between waking up to start a run and submitting the report at the end of the run.

      Show
      The  total  time should represent the amount of time spent by the agent between waking up to start a run and submitting the report at the end of the run.
    • Team:
      Coremunity
    • Sub-team:
    • Sprint:
      Platform Core KANBAN
    • Method Found:
      Customer Feedback
    • CS Priority:
      Reviewed
    • Release Notes:
      Bug Fix
    • Release Notes Summary:
      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.

        Attachments

          Issue Links

            Activity

              jsd-sla-details-panel

                People

                • Assignee:
                  jacob.helwig Jacob Helwig
                  Reporter:
                  adam.bottchen Adam Bottchen
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  14 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: