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

resource evaluation_time in report does not include time spent responding to events

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Normal
    • Resolution: Won't Fix
    • Affects Version/s: PUP 3.8.3
    • Fix Version/s: None
    • Component/s: None
    • Labels:
    • Template:

      Description

      Suppose a manifest contains a resource that takes a substantial amount of time to refresh (for example, an exec resource with a slow command) as a result of a notify/subscribe relationship to another resource. Then the time taken to refresh the resource is not included in the record for that resource in the report.

      For example:

      $ cat test.pp
      file { 'a':
           path    => '/home/vagrant/puppet_test/a',
           content => 'aaa',
           notify  => Exec['b']
      }
       
      exec { 'b':
           command     => 'sleep 3',
           path        => '/usr/bin:/bin',
           refreshonly => true
      }
      $ rm -rf a var && time puppet apply test.pp --report --verbose --vardir=var --evaltrace
      ...
      Info: /Stage[main]/Main/Exec[b]: Starting to evaluate the resource
      Notice: /Stage[main]/Main/Exec[b]: Triggered 'refresh' from 1 events
      Info: /Stage[main]/Main/Exec[b]: Evaluated in 3.01 seconds
      ...
      Info: Creating state file /home/vagrant/puppet_test/var/state/state.yaml
      Notice: Finished catalog run in 3.02 seconds
       
      real	0m4.653s
      user	0m1.279s
      sys	0m0.312s
      

      which correctly shows that the command for `Exec[b]` took 3 seconds to run. However, the report file contains

      $ cat var/reports/*/*.yaml
      ...
        resource_statuses:
      ...
          Exec[b]: !ruby/object:Puppet::Resource::Status
            resource: Exec[b]
            file: /home/vagrant/puppet_test/test.pp
            line: 11
            evaluation_time: 0.000116117
            change_count: 0
            out_of_sync_count: 0
            tags:
              - exec
              - b
              - class
            time: 2015-11-04 19:00:46.679732 +00:00
            events: []
            out_of_sync: false
            changed: false
            resource_type: Exec
            title: b
            skipped: false
            failed: false
            containment_path:
              - Stage[main]
              - Main
              - Exec[b]
      ...
      

      which has no record of these 3 seconds.

      As a workaround, it's possible to extract the real time it took to process resource `Exec[b]` by running with `--evaltrace` and matching up log messages with resource statuses, but that is inconvenient and the existing `evaluation_time` field of the resource status is misleading.

        Attachments

          Activity

            People

            Assignee:
            Unassigned
            Reporter:
            rwbarton Reid Barton
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Zendesk Support