Checkout suddenly much slower on windows environment

[yeu-degroot]

Moved from actions/runner-images#7180

Description

Since a few days, the duration of the actions/checkout@v3 steps on windows-2019 have dramatically increased.
This behavior is seen on all my repos (all private). Below a table showing an example of before/after.

Checkout step	Feb 17th	Feb 21st
1	13s	1m35s
2	8s	47s

The result is a huge increase in build (and billable) time.

The github status page does show some issues around this time frame, but these were all solved:

Platforms affected

• Azure DevOps
• GitHub Actions - Standard Runners
• GitHub Actions - Larger Runners

Runner images affected

• Ubuntu 18.04
• Ubuntu 20.04
• Ubuntu 22.04
• macOS 11
• macOS 12
• Windows Server 2019
• Windows Server 2022

Image version and build link

Current runner version: '2.301.1'
Operating System
  Microsoft Windows Server 2019
  10.0.17763

Private repo

Is it regression?

Yes, sorry private repos

Expected behavior

The build times should be fairly constant.

Actual behavior

Build times explode. Burning down our build minutes too fast.

Repro steps

Compare build times on any windows environment from before Feb 18th with today.

[Tyrrrz]

I have observed this too. Example job: https://github.com/Tyrrrz/CliWrap/actions/runs/4271628026

• Windows – checkout took 4m9s:

• Ubuntu – checkout took <1s:

• macOS – checkout took 3s:

Note that this behavior is pretty inconsistent, and usually checkout completes pretty fast on Windows. But in the event that it is slow, it's only ever slow on Windows.

[dscho]

I've encountered this and debugged it a bit, by heavily instrumenting the transpiled code in dist/index.js. Turns out that there are multiple calls to PowerShell that make a mess by essentially waiting for dozens of seconds. Here is the example run I analyzed:

• here, 1 minute and 14 seconds are spent,
• here, 11 seconds are spent,
• here, 12 seconds are spent,
• here, 11 seconds are spent,

all on this PowerShell call:

(Get-CimInstance -ClassName Win32_OperatingSystem).caption

totaling 1 minute and 48 whopping seconds just to determine a Windows release that the actions/checkout Action has no need to know.

To make things even worse, the same PowerShell invocation also happens multiple times during the post-action:

• 10 seconds here,
• 12 seconds there,
• 11 seconds there and
• 12 seconds here

I do not really understand what changed between Feb 17th and 21st that would explain this slowdown. There has not been a new actions/checkout release since Jan 5th...

[dscho]

I have briefly seen success trying to hard-code the fix of sindresorhus/windows-release#18 into dist/index.js but it does not seem to work when I undelete all the core logic. sigh

At this point, I have to tend to other things, but I thought I'd leave my current findings here in case somebody else can take over (and try things like overriding os.release() to always return 2022 or something like that, before letting @octokit/endpoint initialize its User-Agent string).

[BrettDong]

I made an attempt to avoid calling into windows-releases from the checkout action in #1246.

If you want to try you can use

- uses: BrettDong/checkout@octokit

and see if there is any improvement in time stalled between starting the checkout action and performing actual git operations.

[dscho]

@BrettDong excellent! I tested this and the times are back to decent levels: the entire checkout step takes 11 seconds with your PR. Thank you so much!

[BrettDong]

The fix in #1246 reduces stalled time down to 3 seconds.

During the 3 seconds the workflow is stalled on loading the node.exe from disk to memory for execution. I don't think there is anything I can do to get rid of it.

[Gakk]

I have had a similar issue with large runners with slow checkout and cleanup that I reported to GitHub Support. They concluded that it is related this issue, even though I am not completely convinced.

The screenshot from @Tyrrrz earlier in this issue also shows a slow post checkout (cleanup).

Workflow:

To recreate as a minimum solution, I created a new repository with only a single workflow file, spinning up 3 jobs on default and large runners:

name: Demo Slow Checkout

on:
  workflow_dispatch:

permissions:
  contents: read

jobs:

  doSomething:
  
    name: My Job

    strategy:
      matrix:
        os: [windows-latest, windows-latest-8core, windows-latest-16core]

    runs-on: ${{ matrix.os }}

    steps:
    - name: Checkout
      uses: actions/checkout@8f4b7f84864484a7bf31766abe9204da3cbe65b3 # v3.5.0
      # https://github.com/actions/checkout/releases
      with:
        # Fetch full depth
        fetch-depth: 0

    - name: Work for 15 seconds
      run: Start-Sleep -Seconds 15

In addition to checkout the job has only one other step, and that is to sleep for 15 seconds.

Results:

The jobs executed 10 times, and shows that:

• Checkout
  • Normal time is 19 seconds
  • Large runners use more than twice the time (between 47 and 51 seconds)
• Post Checkout
  • Normal time is 3 seconds
  • Large runners use 15 times more time (between 46 and 49 seconds)

ℹ️ The last row is median and not average, so that any single slow run should interfere with the result.

Findings:

Finding 1:

Every single checkout on the large runners is at least twice as slow as on regular runner, and all the times goes before the actual checkout starts:

Finding 2:

The post checkout (cleanup) is on average 15 times slower as on regular runner, and all the time also goes before any cleanup is started:

Finding 3:

The simple sleep-task on regular runner uses twice the time of the sleep interval. How is it even possible that a sleep for 15 seconds takes almost double the time? This was done with a simple run: Start-Sleep -Seconds 15.

[BrettDong]

You can build something like https://github.com/BrettDong/Cataclysm-DDA/blob/etw/.github/workflows/etw.yml to collect ETL traces in the runner to diagnose what is happening and spending time during checkout.

[myitcv]

@BrettDong

During the 3 seconds the workflow is stalled on loading the node.exe from disk to memory for execution. I don't think there is anything I can do to get rid of it.

This seems like an interesting point in and of itself. Because in actions/runner-images#7320 whilst we report actions/checkout issues, we see much bigger problems during workflows which heavily rely on disk access (i.e. cache hits during test runs).

So if I understand your conclusion, the narrowing down of this to being a disk access issue (or something that limits the effective disk access rate), this is consistent with what we are seeing.

[ScottTodd]

I have had a similar issue with large runners with slow checkout and cleanup that I reported to GitHub Support. They concluded that it is related this issue, even though I am not completely convinced.

Same here - we've noticed that large GitHub-managed Windows runners are substantially slower during checkout. This is not a recent regression for us though - they've been (nearly unuseably) slow for months.

Runner	Checkout time
Self hosted Linux	40s
small GitHub-managed windows (windows-2022)	2m30s
large GitHub-managed Windows	12m

We also have a ticket with GitHub Support, and I've been running experiments for our repo / workflows at iree-org/iree#12051.