[BUG]: PowerShell task startup too slow

[dlaw1912]

New issue checklist

• I searched for existing GitHub issues
• I read pipeline troubleshooting guide
• I checked how to collect logs

Task name

PowerShell

Task version

2.247.1

Issue Description

On our self-hosted machine/agents, there are times when just initialising the PowerShell tasks takes more than a few seconds. Most recently, it took half an hour, so the overall pipeline failed as it exceeded the maximum time. it isn't consistently the same task in the pipeline, but it is only ever a PowerShell task.

This only occurs on interactive agents used for UI tests, agents run as a service use the same scripts but don't suffer the same issue.

Environment type (Please select at least one enviroment where you face this issue)

• Self-Hosted
• Microsoft Hosted
• VMSS Pool
• Container

Azure DevOps Server type

Azure DevOps Server (Please specify exact version in the textbox below)

Azure DevOps Server Version (if applicable)

No response

Operation system

Windows 11

Relevant log output

`2024-12-10T04:21:09.1539764Z ##[section]Starting: My Task
2024-12-10T04:21:11.1704627Z ==============================================================================
2024-12-10T04:21:11.1704969Z Task         : PowerShell
2024-12-10T04:21:11.1705159Z Description  : Run a PowerShell script on Linux, macOS, or Windows
2024-12-10T04:21:11.1706032Z Version      : 2.247.1
2024-12-10T04:21:11.1706214Z Author       : Microsoft Corporation
2024-12-10T04:21:11.1706368Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/powershell
2024-12-10T04:21:11.1706638Z ==============================================================================
2024-12-10T04:51:26.4022849Z Generating script.
2024-12-10T04:51:35.4791933Z Formatted command: . 'C:\MyScript.ps1'`

Full task logs with system.debug enabled

2024-12-18T04:34:44.4883511Z ##[debug]Evaluating condition for step: 'MyTask'
2024-12-18T04:34:44.4894588Z ##[debug]Evaluating: SucceededNode()
2024-12-18T04:34:44.4895346Z ##[debug]Evaluating SucceededNode:
2024-12-18T04:34:44.4917024Z ##[debug]=> True
2024-12-18T04:34:44.7057421Z ##[debug]Result: True
2024-12-18T04:34:45.1122598Z ##[section]Starting: MyTask
2024-12-18T04:34:47.7477566Z ##[debug]Agent running environment resource - Disk:C:\  available:35391.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.39
2024-12-18T04:34:52.8223461Z ##[debug]Agent running environment resource - Disk:C:\  available:35391.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.40
2024-12-18T04:34:57.8220796Z ##[debug]Agent running environment resource - Disk:C:\  available:35391.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.39
2024-12-18T04:35:02.8223000Z ##[debug]Agent running environment resource - Disk:C:\  available:35391.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.39
2024-12-18T04:35:04.4535973Z ==============================================================================
2024-12-18T04:35:04.4537501Z Task         : PowerShell
2024-12-18T04:35:04.4538445Z Description  : Run a PowerShell script on Linux, macOS, or Windows
2024-12-18T04:35:04.4540315Z Version      : 2.247.1
2024-12-18T04:35:04.4541348Z Author       : Microsoft Corporation
2024-12-18T04:35:04.4542437Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/powershell
2024-12-18T04:35:04.4543155Z ==============================================================================
2024-12-18T04:35:07.8219735Z ##[debug]Agent running environment resource - Disk:C:\  available:35391.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.38
2024-12-18T04:35:12.8226800Z ##[debug]Agent running environment resource - Disk:C:\  available:35389.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.37
2024-12-18T04:35:17.8380991Z ##[debug]Agent running environment resource - Disk:C:\  available:35389.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.37
2024-12-18T04:35:22.8569402Z ##[debug]Agent running environment resource - Disk:C:\  available:35388.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.36
2024-12-18T04:35:27.8727802Z ##[debug]Agent running environment resource - Disk:C:\  available:35388.00MB out of 65913.00MB, Memory: used 11MB out of 2588MB, CPU: usage 2.36
2024-12-18T04:35:35.6219978Z ##[debug]Agent running environment resource - Disk:C:\  available:35388.00MB out of 65913.00MB, Memory: used 13MB out of 2588MB, CPU: usage 2.35
2024-12-18T04:35:40.6354306Z ##[debug]Agent running environment resource - Disk:C:\  available:35388.00MB out of 65913.00MB, Memory: used 13MB out of 2588MB, CPU: usage 2.36
2024-12-18T04:35:45.6360126Z ##[debug]Agent running environment resource - Disk:C:\  available:35388.00MB out of 65913.00MB, Memory: used 13MB out of 2588MB, CPU: usage 2.36
2024-12-18T04:35:48.8539208Z ##[debug]Invoking Method: System.Threading.Tasks.Task b__9(). Attempt count: 0
2024-12-18T04:35:50.6659140Z ##[debug]Agent running environment resource - Disk:C:\  available:35387.00MB out of 65913.00MB, Memory: used 14MB out of 2588MB, CPU: usage 2.38
2024-12-18T04:35:55.7059533Z ##[debug]Agent running environment resource - Disk:C:\  available:35387.00MB out of 65913.00MB, Memory: used 14MB out of 2588MB, CPU: usage 2.39
[truncated due to character limit]
2024-12-18T05:16:54.8376684Z ##[debug]Agent running environment resource - Disk:C:\  available:35305.00MB out of 65913.00MB, Memory: used 22MB out of 2588MB, CPU: usage 0.83
2024-12-18T05:16:58.1902510Z ##[debug]Re-evaluate condition on job cancellation for step: 'MyTask'.
2024-12-18T05:16:59.8534080Z ##[debug]Agent running environment resource - Disk:C:\  available:35305.00MB out of 65913.00MB, Memory: used 22MB out of 2588MB, CPU: usage 0.83
2024-12-18T05:19:29.8366096Z ##[debug]PERF: RetryHelper Method:System.Threading.Tasks.Task b__9() : took 2620719.5984 ms
2024-12-18T05:19:29.8370329Z ##[debug]PERF WARNING: RetryHelper Method:System.Threading.Tasks.Task b__9() : took 2620719.5984 ms
2024-12-18T05:20:12.4180374Z ##[error]The operation was canceled.
2024-12-18T05:20:19.1608793Z ##[debug]System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.VisualStudio.Services.Agent.Util.ProcessInvoker.ExecuteAsync(String workingDirectory, String fileName, String arguments, IDictionary`2 environment, Boolean requireExitCodeZero, Encoding outputEncoding, Boolean killProcessOnCancel, InputQueue`1 redirectStandardIn, Boolean inheritConsoleHandler, Boolean keepStandardInOpen, Boolean highPriorityProcess, Boolean continueAfterCancelProcessTreeKillAttempt, CancellationToken cancellationToken) in D:\a\1\s\src\Agent.Sdk\ProcessInvoker.cs:line 376
   at Microsoft.VisualStudio.Services.Agent.ProcessInvokerWrapper.ExecuteAsync(String workingDirectory, String fileName, String arguments, IDictionary`2 environment, Boolean requireExitCodeZero, Encoding outputEncoding, Boolean killProcessOnCancel, InputQueue`1 redirectStandardIn, Boolean inheritConsoleHandler, Boolean keepStandardInOpen, Boolean highPriorityProcess, Boolean continueAfterCancelProcessTreeKillAttempt, CancellationToken cancellationToken) in D:\a\1\s\src\Microsoft.VisualStudio.Services.Agent\ProcessInvoker.cs:line 308
   at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.DefaultStepHost.ExecuteAsync(String workingDirectory, String fileName, String arguments, IDictionary`2 environment, Boolean requireExitCodeZero, Encoding outputEncoding, Boolean killProcessOnCancel, Boolean inheritConsoleHandler, Boolean continueAfterCancelProcessTreeKillAttempt, CancellationToken cancellationToken) in D:\a\1\s\src\Agent.Worker\Handlers\StepHost.cs:line 76
   at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.PowerShell3Handler.RunAsync() in D:\a\1\s\src\Agent.Worker\Handlers\PowerShell3Handler.cs:line 73
   at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.<>c__DisplayClass27_0.<b__9>d.MoveNext() in D:\a\1\s\src\Agent.Worker\TaskRunner.cs:line 406
--- End of stack trace from previous location ---
   at Microsoft.VisualStudio.Services.Agent.Worker.RetryHelper.RetryStep(Func`1 action, Func`2 timeDelayInterval) in D:\a\1\s\src\Agent.Worker\RetryHelper.cs:line 88
   at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.RunAsync() in D:\a\1\s\src\Agent.Worker\TaskRunner.cs:line 406
   at Microsoft.VisualStudio.Services.Agent.Worker.StepsRunner.RunStepAsync(IStep step, CancellationToken jobCancellationToken) in D:\a\1\s\src\Agent.Worker\StepsRunner.cs:line 263
2024-12-18T05:20:19.1625182Z ##[section]Finishing: MyTask 

Repro steps

trigger: none
pr: none

name: My Pipeline $(Date:MMddyy) - $(Rev:rr)
pool:
  name: MyPool
  demands:
   - Agent.Name -equals MyAgent

variables:
  - name: BuildPlatform
    value: 'x64'
    readonly: true
  - name: SYSTEM_ACCESSTOKEN
    value: $(System.AccessToken)
    readonly: true

resources:
  repositories:
    - repository: templates
      type: git
      name: MyTemplates

jobs:
- job: Test
  displayName: 'Run tests'

  steps:
  - task: PowerShell@2
    displayName: 'My Task'
    name: MyTask
    inputs:
      targetType: filePath
      filePath: 'C:\MyScript.ps1'
      errorActionPreference: 'continue'
      failOnStderr: true

[v-vinaykoora]

@dlaw1912 Verified the error log which you have shared and found it got stuck before it started the task execution. It's an issue with agent which you have used for it as it got stuck after verifying the space on the agent.

It's not a task issue and issue from agent. Please check what happened during that duration. Please also let us know did you faced the issue again or it has happened only once. As you were using self hosted agent, please verify from your end on the agent.

2024-12-18T05:16:54.8376684Z ##[debug]Agent running environment resource - Disk:C:\ available:35305.00MB out of 65913.00MB, Memory: used 22MB out of 2588MB, CPU: usage 0.83
2024-12-18T05:16:58.1902510Z ##[debug]Re-evaluate condition on job cancellation for step: 'MyTask'.
2024-12-18T05:16:59.8534080Z ##[debug]Agent running environment resource - Disk:C:\ available:35305.00MB out of 65913.00MB, Memory: used 22MB out of 2588MB, CPU: usage 0.83
2024-12-18T05:19:29.8366096Z ##[debug]PERF: RetryHelper Method:System.Threading.Tasks.Task b__9() : took 2620719.5984 ms
2024-12-18T05:19:29.8370329Z ##[debug]PERF WARNING: RetryHelper Method:System.Threading.Tasks.Task b__9() : took 2620719.5984 ms
2024-12-18T05:20:12.4180374Z ##[error]The operation was canceled.
2024-12-18T05:20:19.1608793Z ##[debug]System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()

[v-vinaykoora]

@dlaw1912 Any update on this request

[v-vinaykoora]

@dlaw1912 Any update on this request

[dlaw1912]

It has previously happened multiple times on multiple agents, and there is always space on the agent host.

I've run Windows updates on the agent hosts (these are Hyper-V hosts reset to the same checkpoint for every run), and the pipeline had been running fine for about a week, but it has now failed overnight again.

The only difference I can see last night is another UI agent was running at the same time on a separate Hyper-V host, but both hosts exist on the same computer, but each should have sufficient resources to run.

[v-vinaykoora]

@dlaw1912 Thanks for the confirmation, i hope the issue is not from task side and that was from the agent side. Even, the earlier issue had occurred due to an agent issue, not from task side.

Could you please confirm whether we can proceed with closure of it