Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Mihai Buzgau updated an issue Puppet / PUP-10352 Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows Change By: Mihai Buzgau Sprint: NW - 2020-03-17 , NW - 2020-04-29 Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.42655.1587463140034%40Atlassian.JIRA.
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title
Mihai Buzgau commented on PUP-10352
Re: Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
As a next step, would it be possible to get the output from the following:
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"
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Henry Wang commented on PUP-10352 Re: Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows Right now we are asking Customer to enable debug mode and check if the above child is slow. Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.39770.1586997120024%40Atlassian.JIRA.
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Henry Wang commented on PUP-10352 Re: Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows 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
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title
Mihai Buzgau commented on 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
}
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Austin Boyd updated an issue Puppet / PUP-10352 Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows Change By: Austin Boyd Zendesk Ticket Count: 1 2 Zendesk Ticket IDs: 38131 ,38849 Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.38803.1586946780147%40Atlassian.JIRA.
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Henry Wang commented on PUP-10352 Re: Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows 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",
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Mihai Buzgau commented on 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 Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.13093.1584344880027%40Atlassian.JIRA.
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Mihai Buzgau updated an issue Puppet / PUP-10352 Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows Change By: Mihai Buzgau Sprint: PR NW - Triage 2020-03-17 Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.5489.1583402160026%40Atlassian.JIRA.
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Mihai Buzgau updated an issue Puppet / PUP-10352 Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows Change By: Mihai Buzgau Story Points: 3 Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.5482.1583400780029%40Atlassian.JIRA.
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Josh Cooper moved an issue Puppet / 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 This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You
Jira (PUP-10352) Puppet agent total run time reported doesn't match time elapsed between Start and End event logs in Windows
Title: Message Title Josh Cooper updated an issue Puppet / 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 Affects Version/s: PUP 5.5.14 Add Comment This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-bugs/JIRA.347072.158219188.3839.1583335680227%40Atlassian.JIRA.
