Git clone of curl repository stuck inside Windows container

[mback2k]

• I was not able to find an open or closed issue matching what I'm seeing

Setup

• Which version of Git for Windows are you using? Is it 32-bit or 64-bit?

$ git --version --build-options

git version 2.19.1.windows.1
cpu: x86_64
built from commit: 11a3092e18f2201acd53e45aaa006f1601b6c02a
sizeof-long: 4
sizeof-size_t: 8

• Which version of Windows are you running? Vista, 7, 8, 10? Is it 32-bit or 64-bit?

$ cmd.exe /c ver

Microsoft Windows [Version 10.0.17134.285]
Windows Server Version 1803, 64-bit, headless

• What options did you set as part of the installation? Or did you choose the
  defaults?

# One of the following:
> type "C:\Program Files\Git\etc\install-options.txt"
> type "C:\Program Files (x86)\Git\etc\install-options.txt"
> type "%USERPROFILE%\AppData\Local\Programs\Git\etc\install-options.txt"
$ cat /etc/install-options.txt

Editor Option: VIM
Custom Editor Path:
Path Option: Cmd
SSH Option: OpenSSH
CURL Option: OpenSSL
CRLF Option: CRLFAlwaysBash Terminal Option: MinTTY
Performance Tweaks FSCache: EnabledUse Credential Manager: Enabled
Enable Symlinks: Enabled
Enable Builtin Rebase: Disabled
Enable Builtin Stash: Disabled

• Any other interesting things about your environment that might be related
  to the issue you're seeing?

This issue is occurring during manual clones via docker exec and was discovered while moving my buildbots for the curl and libssh2 projects into docker container. Please see an example build here which failed due to timed out clone after 20 minutes:

• git clone
• git fetch

For curl it always fails due to timing out, but for libssh2 it works most of the time. So I guess that it has something to do with the huge size of the curl repository. At some point it also randomly worked for the curl repository, see this build output.

Details

• Which terminal/shell are you running Git from? e.g Bash/CMD/PowerShell/other

docker exec from bash on Debian to control a remote Windows Docker host.

• What commands did you run to trigger this issue? If you can provide a
  Minimal, Complete, and Verifiable example
  this will help us understand the issue.

DOCKER_HOST=a.b.c.d:2376 docker exec -e GIT_CURL_VERBOSE=1 -e GIT_TRACE=1 -e GIT_TRACE_PACK_ACCESS=1 -e GIT_TRACE_PACKET=1 -e GIT_TRACE_PERFORMANCE=1 -e GIT_TRACE_SETUP=1 -e GIT_TRACE_SHALLOW=1 [my-docker-container] git clone https://github.com/curl/curl.git curl_test

The docker container is created from this Dockerfile.

The target directory is inside the container and not a docker volume.

• What did you expect to occur after running these commands?

Successful clone in a few seconds.

• What actually happened instead?

Git clone is stuck and is normally killed by my buildbot after 20 minutes, in this case I killed it manually. Please see attached git_clone_output.txt.

• If the problem was occurring with a specific repository, can you provide the
  URL to that repository to help us with testing?

https://github.com/curl/curl.git

[mback2k]

A minimal Dockerfile to reproduce the state of the docker container installed with Git would be:

# escape=`

FROM microsoft/windowsservercore:1803

SHELL ["powershell", "-command"]

ARG GIT_X64="https://github.com/git-for-windows/git/releases/download/v2.19.1.windows.1/Git-2.19.1-64-bit.exe"
ADD ${GIT_X64} C:\Windows\Temp\Git-64-bit.exe

RUN Start-Process -FilePath "C:\Windows\Temp\Git-64-bit.exe" -ArgumentList /VERYSILENT, /NORESTART, /NOCANCEL, /SP- -NoNewWindow -PassThru -Wait; `
    Remove-Item @('C:\Windows\Temp\*', 'C:\Users\*\Appdata\Local\Temp\*') -Force -Recurse;

[dscho]

@mback2k that sounds as if something got stuck somewhere... can you instrument Git's code, say, to output some debug messages in cmd_index_pack()?

[mback2k]

@dscho I am working on additional debug output using your Git for Windows SDK. In the meantime I performed some additional tries and it seems like it just takes very long:

20:36:39.634573 run-command.c:637       trace: run_command: git index-pack --stdin --fix-thin '--keep=fetch-pack 6576 on 3e7e41c7b6a6' --check-self-contained-and-connected --pack_header=2,138293
20:36:39.669572 exec-cmd.c:236          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
20:36:39.673573 trace.c:318             setup: git_dir: C:/Buildbot/curl_test2/.git
20:36:39.673573 trace.c:319             setup: git_common_dir: C:/Buildbot/curl_test2/.git
20:36:39.673573 trace.c:320             setup: worktree: C:/Buildbot
20:36:39.673573 trace.c:321             setup: cwd: C:/Buildbot
20:36:39.673573 trace.c:322             setup: prefix: (null)
20:36:39.673573 git.c:415               trace: built-in: git index-pack --stdin --fix-thin '--keep=fetch-pack 6576 on 3e7e41c7b6a6' --check-self-contained-and-connected --pack_header=2,138293
20:53:44.436875 pkt-line.c:80           packet:          git< 0000
20:53:44.436875 pkt-line.c:80           packet:     sideband< 0000
20:53:58.832677 trace.c:420             performance: 1039.175899400 s: git command: git index-pack --stdin --fix-thin '--keep=fetch-pack 6576 on 3e7e41c7b6a6' --check-self-contained-and-connected --pack_header=2,138293
20:53:58.842678 trace.c:420             performance: 1039.798131900 s: git command: git fetch-pack --stateless-rpc --stdin --lock-pack --thin --check-self-contained-and-connected --cloning --no-progress https://github.com/curl/curl.git/

As you can see from these logs, it takes roughly 17 minutes to receive the index pack in this case. I will try to increase the build timeout for my builders while also figuring out the bottleneck using additional debug messages.

[mback2k]

This problem seems to have been caused by extremely slow container and network performance due to nested virtualization. After finally being able to setup VLANs with the hosting provider, nested virtualization is no longer required and therefore the performance issue could be solved. This had nothing to do with Git for Windows.

[dscho]

Excellent analysis! I am glad you figured it out.

[mback2k]

Unfortunately I am again experiencing this issue after some successful clones. It still seems to be a performance issue inside my process-level isolation Windows Container:

Receiving objects:   0% (1106/138559), 660.01 KiB | 23.00 KiB/s

Any other suggestions where to look? The performance speed maxes at 28.00 KiB/s. At the moment I am thinking this Windows Container issue is the root cause: docker/for-win#698.

I will update this issue in case others run into a similar situation later on.

[mback2k]

After multiple days I can probably finally confirm that disabling receive segment coalescing (RSC) while using Docker for Windows or WinNAT solves the performance issues I experienced. See microsoft/hcsshim#371 for more information.