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

compile profiler metrics are incorrect

    Details

    • Type: Bug
    • Status: Accepted
    • Priority: Normal
    • Resolution: Unresolved
    • Affects Version/s: PUP 4.2.1
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      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)
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                josh Josh Cooper
              • Votes:
                0 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:

                  Zendesk Support