Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows

38 views
Skip to first unread message

Josh Cooper (Jira)

unread,
Mar 4, 2020, 10:28:03 AM3/4/20
to puppe...@googlegroups.com
Josh Cooper moved an issue
 
Puppet / Bug PUP-10352
Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Change By: Josh Cooper
Component/s: Windows
Component/s: Windows
Key: PA PUP - 3139 10352
Affects Version/s: puppet-agent 5.5.14
Project: Puppet Agent
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935)
Atlassian logo

Josh Cooper (Jira)

unread,
Mar 4, 2020, 10:28:04 AM3/4/20
to puppe...@googlegroups.com
Josh Cooper updated an issue
Change By: Josh Cooper
Affects Version/s: PUP 5.5.14

Mihai Buzgau (Jira)

unread,
Mar 5, 2020, 4:33:03 AM3/5/20
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
Change By: Mihai Buzgau
Story Points: 3

Mihai Buzgau (Jira)

unread,
Mar 5, 2020, 4:56:03 AM3/5/20
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
Change By: Mihai Buzgau
Sprint: PR NW - Triage 2020-03-17

Mihai Buzgau (Jira)

unread,
Mar 16, 2020, 3:48:03 AM3/16/20
to puppe...@googlegroups.com
Mihai Buzgau commented on Bug PUP-10352
 
Re: Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows

The report that is sent to the server only covers configurer run_interval metrics, starting from here: https://github.com/puppetlabs/puppet/blob/master/lib/puppet/configurer.rb#L238

Before this there are some steps that are happening but not accounted for, like the initial run of Facter, ensuring the puppet cache folder structure exist, etc.

 

The initial message Executing agent with arguments on Windows happens right at the start of the Puppet Agent run: https://github.com/puppetlabs/puppet/blob/master/ext/windows/service/daemon.rb#L81, so the differences between the two events represent the full Puppet Agent run.

 

I've created the following ticket to improve the metrics that are reported to the server: https://tickets.puppetlabs.com/browse/PUP-10371

Henry Wang (Jira)

unread,
Apr 15, 2020, 6:10:02 AM4/15/20
to puppe...@googlegroups.com
Henry Wang commented on Bug PUP-10352

Hi team, here is the actual customer concern:

Is it fair to say then that the timing of the manual puppet runs with 'puppet agent -t' and the puppet agent triggering its own 30 minute interval run should take about the same amount of time? That would be my expectation and they should roughly be doing the same activities in spite of how they are triggered - correct?

May I know if this is the case, technically? At least from logging, the logs are different between the two for the Windows node. 

An interval run (1:25:32 - 1:26:43), 70s:

1:25:32 AM: "Executing agent with arguments:"
 
1:26:43 AM: "Applied catalog in 1.82 seconds"

A bolt triggered manual run (10:07:52-10:08:20), less than 30 seconds:

[10:07:52] rstuart@nix2
 
/home/rstuart: date ; bolt command run 'puppet agent -t' --targets pup-tst-w19-01 --password-prompt --user 'PLUTO\a-rstuart'
 
Fri Feb 14 10:07:54 AEST 2020
 
Please enter your password:
 
CLI arguments ["user", "password"] may be overridden by Inventory: /home/rstuart/.puppetlabs/bolt/inventory.yaml
 
Started on pup-tst-w19-01...
 
Finished on pup-tst-w19-01:
 
STDOUT:
 
Info: Using configured environment 'master'
 
Info: Retrieving pluginfacts
 
Info: Retrieving plugin
 
Info: Retrieving locales
 
Info: Loading facts
 
Info: Caching catalog for pup-tst-w19-01.creditlink.com.au
 
Info: Applying configuration version '841c9ce69f7997d312d97bbb06b0ce26c1f7bb6b'
 
Notice: Applied catalog in 1.81 seconds
 
Successful on 1 target: pup-tst-w19-01
 
Ran on 1 target in 20.24 sec
 
[10:08:20] rstuart@nix2/home/rstuart:

In both cases, Puppet dashboard reports a 20s puppet run time and that is why you want to improve the metrics collection. It is cool. But according to the log stamps above, technically an interval run takes a longer time (in this case, more than doubled time) than a manual agent run. May we know why the difference here, regardless of what Puppet reports calculation is? Is it because of a logging issue? Or is it because more processes needed for an interval run?

Thanks.

 

 

Austin Boyd (Jira)

unread,
Apr 15, 2020, 6:33:03 AM4/15/20
to puppe...@googlegroups.com
Austin Boyd updated an issue
 
Change By: Austin Boyd
Zendesk Ticket Count: 1 2
Zendesk Ticket IDs: 38131 ,38849

Mihai Buzgau (Jira)

unread,
Apr 15, 2020, 11:10:04 AM4/15/20
to puppe...@googlegroups.com
Mihai Buzgau commented on Bug PUP-10352
 
Re: Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows

Henry Wang There are some differences between agent -t and the agent executions that are done by the Puppet Agent service.

The Puppet Agent service starts a new child process: https://github.com/puppetlabs/puppet/blob/master/ext/windows/service/daemon.rb#L82 while agent -t does not start a new process. But this should not double the execution time.

The log Executing agent with arguments is logged before the child process is started and is only present while running Puppet as a service.

The Applied catalog* log is always logged.

I've quickly set up a PE deployment and connected a Windows node to it. I was not able to reproduce the time discrepancy that you've mentioned. 

Using puppet agent -t:

PS C:\Users\Administrator> (Measure-Command -Expression { puppet agent -t}).TotalSeconds
 
5.7636066

To measure the service runtime, I've used the following PowerShell script that checks the time between the two events:

$agent_start = $null
 
Get-WinEvent -LogName 'Application' | Where-Object { $_.ProviderName -Match 'Puppet' } | Sort-Object -Property TimeCreated | ForEach-Object {
 
    if ($_.Message -match "Executing agent with arguments") {
 
        Write-Output $_
 
        $agent_start = $_.TimeCreated
 
    }
 
    if (($_.Message -match "Applied") -and ($agent_start -ne $null))  {
 
        Write-Output $_
 
        $agent_end = $_.TimeCreated
 
        $runtime = (New-TimeSpan -Start $agent_start -End $agent_end).TotalSeconds
 
        Write-Output "Total Agent time: $runtime"
 
        $agent_start = $null
 
    }
 
}

This produced a similar puppet agent run time to puppet agent -t (please note that I've set the runinterval to_180)_ :

   ProviderName: PuppetTimeCreated                     Id LevelDisplayName Message                                                                                                                                   
-----------                     -- ---------------- -------                                                                                                                                   
4/15/2020 1:19:36 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:19:42 PM             1 Information      Applied catalog in 0.09 seconds                                                                                                           
Total Agent time: 5.7094465
 
4/15/2020 1:22:38 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:22:43 PM             1 Information      Applied catalog in 0.09 seconds                                                                                                           
Total Agent time: 5.4922873
 
4/15/2020 1:25:40 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:25:46 PM             1 Information      Applied catalog in 0.09 seconds                                                                                                           
Total Agent time: 5.5160034
 
4/15/2020 1:28:42 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:28:48 PM             1 Information      Applied catalog in 0.09 seconds                                                                                                           
Total Agent time: 5.6563542
 
4/15/2020 1:31:45 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:31:50 PM             1 Information      Applied catalog in 0.10 seconds                                                                                                           
Total Agent time: 5.5539996
 
4/15/2020 1:34:47 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:34:52 PM             1 Information      Applied catalog in 0.11 seconds                                                                                                           
Total Agent time: 5.6095823
 
4/15/2020 1:37:49 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:37:55 PM             1 Information      Applied catalog in 0.10 seconds                                                                                                           
Total Agent time: 5.5313138
 
4/15/2020 1:40:51 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:40:57 PM             1 Information      Applied catalog in 0.10 seconds                                                                                                           
Total Agent time: 5.3925027
 
4/15/2020 1:43:53 PM             1 Information      Executing agent with arguments:                                                                                                           
4/15/2020 1:43:59 PM             1 Information      Applied catalog in 0.09 seconds                                                                                                           
Total Agent time: 5.4857205

 

It would be great if you could provide access to your provide us access to your PE deployment to further investigate the issue.

Thanks.

Henry Wang (Jira)

unread,
Apr 15, 2020, 8:25:03 PM4/15/20
to puppe...@googlegroups.com
Henry Wang commented on Bug PUP-10352

Hi Mihai,

Thanks for the tests. Unfortunately, the issue is reported not from my side but from the customer. But I indeed find something confusing me:

I just checked my latest Puppet Interval Run for my Windows:

11:58:52 Applied catalog in 0.16 seconds
 
11:58:42 Executing agent with arguments

It looks like the log time is matching the "0.16 seconds". From Puppet console, the metrics are:

Run began:2020-04-15 23:58 Z
 
Catalog submitted:2020-04-15 23:58 Z
 
Run ended:2020-04-15 23:58 Z
 
Report received:2020-04-15 23:58 Z
 
 
 
Total runtime (sec):6.78
 
Config retrieval time (sec):0.72
 
Fact generation (sec):3.29
 
Transaction evaluation (sec):0.15
 
Convert catalog (sec):0.38
 
Node retrieval (sec):0.27
 
Plugin sync (sec):1.93
 
Time to apply (sec):0.16

This doesn't comply with what the customer has observed as reported above...

My Windows lab IP: 10.234.5.100. The credential is using P9 Windows Credentials.

Puppet MoM is 10.234.5.75 if u want to go for the report.

 

Henry Wang (Jira)

unread,
Apr 15, 2020, 8:32:04 PM4/15/20
to puppe...@googlegroups.com
Henry Wang commented on Bug PUP-10352

Right now we are asking Customer to enable debug mode and check if the above child is slow.

Mihai Buzgau (Jira)

unread,
Apr 16, 2020, 4:34:04 AM4/16/20
to puppe...@googlegroups.com
Mihai Buzgau commented on Bug PUP-10352

As a next step, would it be possible to get the output from the following:

  1. Time it took the agent as a service to run.

Can be achieved by running the following script

$agent_start = $null
 
Get-WinEvent -FilterHashTable @{ LogName = 'Application'; StartTime = (Get-Date).AddDays(-1);} | Where-Object { $_.ProviderName -Match 'Puppet' } | Sort-Object -Property TimeCreated | ForEach-Object {
 
    if ($_.Message -match "Executing agent with arguments") {
 
        Write-Output $_
 
        $agent_start = $_.TimeCreated
 
    }
 
    if (($_.Message -match "Applied") -and ($agent_start -ne $null))  {
 
        Write-Output $_
 
        $agent_end = $_.TimeCreated
 
        $runtime = (New-TimeSpan -Start $agent_start -End $agent_end).TotalSeconds
 
        Write-Output "Total Agent time: $runtime"
 
        $agent_start = $null
 
    }
 
}

This retrieves the agent run times for all the agent runs in the past day.

2. Get the agent -t  time.

This can be achieved using the following command:

(Measure-Command -Expression { puppet agent -t}).TotalSeconds

The commands should be executed on the same host and preferably the script at 1. first.

Mihai Buzgau (Jira)

unread,
Apr 21, 2020, 5:59:04 AM4/21/20
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
 
Change By: Mihai Buzgau
Sprint: NW - 2020-03-17 , NW - 2020-04-29
Reply all
Reply to author
Forward
0 new messages