Vcpkg: vcvarsall.bat hangs for a long time

[gvanem]

During any vcpkg install command, I see that CreateProcessW( ...vcvarsall.bat) hangs for approx. 1 minute seeming doing nothing. But probably it the Powershell with this cmd-line:

powershell.exe -NoProfile -Command "& {if($PSVersionTable.PSVersion.Major -ge 3){Import-Module 'f:\gv\vc_2019\Common7\Tools\\Microsoft.VisualStudio.DevShell.dll'; Send-VsDevShellTelemetry -NewInstanceType Cmd; }}" 

Environment

• OS: Win-10.
• Compiler: MSVC-2019, 19.24.28319 for x86

To Reproduce

vcpkg --debug install dbg-macro:x86-windows
...
Installing package dbg-macro[core]:x86-windows... done
Elapsed time for package dbg-macro:x86-windows: 1.724 min
907 us (103562313 us)

For reference a git clone https://github.com/sharkdp/dbg-macro . takes 2 seconds here.

[NancyLi1013]

Hi @gvanem
Thanks for posting this issue.
I cannot reproduce this issue on my local powershell with MSVC 19.25.28610.4.
I also want to confirm what this issue have any effects on you.

Here are the test results on my local:

PS F:\Files\vcpkg\vcpkg> .\vcpkg.exe --debug install dbg-macro:x86-windows
[DEBUG] Using vcpkg-root: F:\Files\vcpkg\vcpkg
Your feedback is important to improve Vcpkg! Please take 3 minutes to complete our survey by running: vcpkg contact --survey
Computing installation plan...
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\cmake-3.14.0-windows\cmake-3.14.0-win32-x86\bin\cmake.exe" --version)
[DEBUG] cmd_execute_and_stream_data() returned 0 after   646498 us
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\cmake-3.14.0-windows\cmake-3.14.0-win32-x86\bin\cmake.exe"  -P "F:/Files/vcpkg/vcpkg/buildtrees/0.vcpkg_tags.cmake")
[DEBUG] cmd_execute_and_stream_data() returned 0 after  1065668 us
The following packages will be built and installed:
    dbg-macro[core]:x86-windows
Starting package 1/1: dbg-macro:x86-windows
Building package dbg-macro[core]:x86-windows...
[DEBUG] <abientries>
[DEBUG] CONTROL|15a1073939448248568bcefa37a695b886514705
[DEBUG] portfile.cmake|61af418ad28700d88cdddb4296d0b22a095b0b46
[DEBUG] cmake|3.14.0
[DEBUG] powershell|ab1effc926b000a6adc12198a1886514ec203621a53b0cd7ec1cd9a8225dccda7e857feaabcfba4004bea73129b986abaad777c4573f44e0af70411226ce08b0
[DEBUG] vcpkg_fixup_cmake_targets|dac334f3bf50b8262be92623168023aa565aa729
[DEBUG] post_build_checks|2
[DEBUG] triplet|e8dc96fd479b53bb0e6748625827c8268017e35a
[DEBUG] features|core
[DEBUG] </abientries>
[DEBUG] CreateProcessW("C:\Program Files (x86)\Microsoft Visual Studio\Installer\vswhere.exe" -all -prerelease -legacy -products * -format xml)
[DEBUG] cmd_execute_and_stream_data() returned 0 after   163741 us
[DEBUG] Found path: C:\Program Files\Git\cmd\git.exe
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\git-2.25.1-1-windows\mingw32\bin\git.exe" --version)
[DEBUG] cmd_execute_and_stream_data() returned 0 after  1678764 us
[DEBUG] CreateProcessW(cmd /c ""C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Auxiliary\Build\vcvarsall.bat" -vcvars_ver=14.2 amd64_x86   2>&1 <NUL" & echo cdARN4xjKueKScMy9C6H& set)
[DEBUG] cmd_execute_and_stream_data() returned 0 after 59498481 us
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\cmake-3.14.0-windows\cmake-3.14.0-win32-x86\bin\cmake.exe" "-DCMD=BUILD" "-DPORT=dbg-macro" "-DCURRENT_PORT_DIR=F:/Files/vcpkg/vcpkg/ports/dbg-macro" "-DVCPKG_ROOT_PATH=F:/Files/vcpkg/vcpkg" "-DTARGET_TRIPLET=x86-windows" "-DTARGET_TRIPLET_FILE=F:\Files\vcpkg\vcpkg\triplets\x86-windows.cmake" "-DVCPKG_PLATFORM_TOOLSET=v142" "-DVCPKG_USE_HEAD_VERSION=0" "-DDOWNLOADS=F:/Files/vcpkg/vcpkg/downloads" "-D_VCPKG_NO_DOWNLOADS=0" "-D_VCPKG_DOWNLOAD_TOOL=BUILT_IN" "-DFEATURES=core" "-DALL_FEATURES=" "-DVCPKG_CONCURRENCY=3" "-DGIT=F:/Files/vcpkg/vcpkg/downloads/tools/git-2.25.1-1-windows/mingw32/bin/git.exe" -P "F:/Files/vcpkg/vcpkg/scripts/ports.cmake")
-- Downloading https://github.com/sharkdp/dbg-macro/archive/4409d8428baf700873bcfee42e63bbca6700b97e.tar.gz...
-- Extracting source F:/Files/vcpkg/vcpkg/downloads/sharkdp-dbg-macro-4409d8428baf700873bcfee42e63bbca6700b97e.tar.gz
-- Using source at F:/Files/vcpkg/vcpkg/buildtrees/dbg-macro/src/ca6700b97e-fe8b18b5a0
[DEBUG] cmd_execute() returned 0 after 7617448 us
-- Performing post-build validation
-- Performing post-build validation done
Building package dbg-macro[core]:x86-windows... done
Installing package dbg-macro[core]:x86-windows...
Installing package dbg-macro[core]:x86-windows... done
Elapsed time for package dbg-macro:x86-windows: 2.612 min

Total elapsed time: 2.612 min

[DEBUG] F:\Files\vcpkg\vcpkg\toolsrc\src\vcpkg\install.cpp(751)
[DEBUG] Exiting after 165864381 us (165848718 us)

[gvanem]

@NancyLi1013 Your cmd /C of vcvarsall.bat is pretty long too; 1 min (59498481 us). Same as mine; what's it doing? Your total is 2.612 min so there are some unaccounted activity here.

[NancyLi1013]

@gvanem
Could you please run
C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Auxiliary\Build\vcvarsall.bat" -vcvars_ver=14.2 amd64_x86 in cmdwindows and check how long it will take?

If it is still pretty long, could you please update Visual Studio 2019 to 16.5.0 and try it again?

[gvanem]

Approx 2 sec.

[NancyLi1013]

I also do several tests on different machines or different directories about this issue.
It seemed that it took a longer time when executed vcvarsall.batfor the first time. Then if I debug ports again, it will take less time than before.

And now the time seems to be normal on my local machine.
Personally, this might be related with our test environment.
Since I test it on the same machine with the same Visual Studio 2019 in different folders, the results are different too.

Does this issue always exist on your machine now?

PS F:\Files\vcpkg\vcpkg> .\vcpkg.exe --debug install dbg-macro:x64-windows
[DEBUG] Using vcpkg-root: F:\Files\vcpkg\vcpkg
Computing installation plan...
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\cmake-3.14.0-windows\cmake-3.14.0-win32-x86\bin\cmake.exe" --version)
[DEBUG] cmd_execute_and_stream_data() returned 0 after  4701551 us
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\cmake-3.14.0-windows\cmake-3.14.0-win32-x86\bin\cmake.exe"  -P "F:/Files/vcpkg/vcpkg/buildtrees/0.vcpkg_tags.cmake")
[DEBUG] cmd_execute_and_stream_data() returned 0 after    65888 us
The following packages will be built and installed:
    dbg-macro[core]:x64-windows
Starting package 1/1: dbg-macro:x64-windows
Building package dbg-macro[core]:x64-windows...
[DEBUG] <abientries>
[DEBUG] CONTROL|15a1073939448248568bcefa37a695b886514705
[DEBUG] portfile.cmake|61af418ad28700d88cdddb4296d0b22a095b0b46
[DEBUG] cmake|3.14.0
[DEBUG] powershell|ab1effc926b000a6adc12198a1886514ec203621a53b0cd7ec1cd9a8225dccda7e857feaabcfba4004bea73129b986abaad777c4573f44e0af70411226ce08b0
[DEBUG] vcpkg_fixup_cmake_targets|dac334f3bf50b8262be92623168023aa565aa729
[DEBUG] post_build_checks|2
[DEBUG] triplet|3eab5c64d9cf628fc0aec277fde66dbdc69b8516
[DEBUG] features|core
[DEBUG] </abientries>
[DEBUG] CreateProcessW("C:\Program Files (x86)\Microsoft Visual Studio\Installer\vswhere.exe" -all -prerelease -legacy -products * -format xml)
[DEBUG] cmd_execute_and_stream_data() returned 0 after    49096 us
[DEBUG] Found path: C:\Program Files\Git\cmd\git.exe
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\git-2.25.1-1-windows\mingw32\bin\git.exe" --version)
[DEBUG] cmd_execute_and_stream_data() returned 0 after   124874 us
[DEBUG] CreateProcessW(cmd /c ""C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Auxiliary\Build\vcvarsall.bat" -vcvars_ver=14.2 amd64   2>&1 <NUL" & echo cdARN4xjKueKScMy9C6H& set)
************vcvarsall.bat time used: 2997 ms************
[DEBUG] cmd_execute_and_stream_data() returned 0 after  2998600 us
[DEBUG] CreateProcessW("F:\Files\vcpkg\vcpkg\downloads\tools\cmake-3.14.0-windows\cmake-3.14.0-win32-x86\bin\cmake.exe" "-DCMD=BUILD" "-DPORT=dbg-macro" "-DCURRENT_PORT_DIR=F:/Files/vcpkg/vcpkg/ports/dbg-macro" "-DVCPKG_ROOT_PATH=F:/Files/vcpkg/vcpkg" "-DTARGET_TRIPLET=x64-windows" "-DTARGET_TRIPLET_FILE=F:\Files\vcpkg\vcpkg\triplets\x64-windows.cmake" "-DVCPKG_PLATFORM_TOOLSET=v142" "-DVCPKG_USE_HEAD_VERSION=0" "-DDOWNLOADS=F:/Files/vcpkg/vcpkg/downloads" "-D_VCPKG_NO_DOWNLOADS=0" "-D_VCPKG_DOWNLOAD_TOOL=BUILT_IN" "-DFEATURES=core" "-DALL_FEATURES=" "-DVCPKG_CONCURRENCY=3" "-DGIT=F:/Files/vcpkg/vcpkg/downloads/tools/git-2.25.1-1-windows/mingw32/bin/git.exe" -P "F:/Files/vcpkg/vcpkg/scripts/ports.cmake")
-- Using cached F:/Files/vcpkg/vcpkg/downloads/sharkdp-dbg-macro-4409d8428baf700873bcfee42e63bbca6700b97e.tar.gz
-- Using source at F:/Files/vcpkg/vcpkg/buildtrees/dbg-macro/src/ca6700b97e-fe8b18b5a0
[DEBUG] cmd_execute_and_stream_data() returned 0 after   151357 us
-- Performing post-build validation
-- Performing post-build validation done
Building package dbg-macro[core]:x64-windows... done
Installing package dbg-macro[core]:x64-windows...
Installing package dbg-macro[core]:x64-windows... done
Elapsed time for package dbg-macro:x64-windows: 3.646 s

Total elapsed time: 3.646 s

[DEBUG] F:\Files\vcpkg\vcpkg\toolsrc\src\vcpkg\install.cpp(749)
[DEBUG] Exiting after 8700764 us (8686815 us)

[gvanem]

It's hard to tell since a vcpkg remove dbg-macro does not remove every trace of that package.
I even had to remove it from the status file. Hence vcvarsall.bat (or some Powershell) stuff may have less work to do the 2nd time I try to install it.

I find this all odd and confusing.

And yes, the issue remains. Powershell is doing something lengthy:

powershell.exe  -NoProfile -Command "& {if($PSVersionTable.PSVersion.Major -ge 3){Import-Module 'f:\gv\vc_2019\Common7\Tools\\Microsoft.VisualStudio.DevShell.dll'; Send-VsDevShellTelemetry -NewInstanceType Cmd; }}" 

for approx 1.5 minutes.

[NancyLi1013]

@gvanem Could you please tell us where you get the following command?
powershell.exe -NoProfile -Command "& {if($PSVersionTable.PSVersion.Major -ge 3){Import-Module 'f:\gv\vc_2019\Common7\Tools\\Microsoft.VisualStudio.DevShell.dll'; Send-VsDevShellTelemetry -NewInstanceType Cmd; }}"

[heydojo]

Does the same thing happen if from a command prompt (win command processor cmd.exe window, not powershell) you do the following:

SETLOCAL
git clone https://github.com/Microsoft/vcpkg
cd vcpkg

and then:

CALL "C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Auxiliary\Build\vcvarsall.bat" -vcvars_ver=14.2 amd64_x86

followed by:

CALL .\bootstrap-vcpkg.bat -disableMetrics
vcpkg install dbg-macro:x86-windows

Also, where are you getting the vcpkg --debug switch from?
vcpkg /? doesn't list it as an option, nor is it listed in README.md.

Thanks.

[gvanem]

@NancyLi1013 I saw that command in Process Explorer spawned from vcpkg.

@heydojo --debug is an undocumented option. That maybe tells more about the documentation.

[TrentWeiss]

I am experiencing the exact same issue.

The issue first popped up when I installed the most recent batch of Windows 10 updates (version Version 10.0.18363.778) and upgraded Visual Studio 2019 to the most recent version (16.5.4).

any ".vcpkg install" command hangs for about 2 minutes and then proceeds as normal.

[Neumann-A]

Same issue... probably related to a Windows update the last few days.
Maybe related to KB4549951 removing it did not help
I noted that the change date of my vcvarsall.bat is 15.04.2020 so it is probably related to that?!?

[Neumann-A]

completly removing and reinstalling VS via the Installer helped me solve the problem.

[NancyLi1013]

Thanks for your info @Neumann-A .
@gvanem and @Electric-Turtle
Could you please try to reinstalling Visual Studio 2019 and try this again?

[Neumann-A]

@NancyLi1013: Seems to not matter it will go back up to 200 seconds after a while.

[Neumann-A]

So I tried running vcpkg in Visual Studio 2019 to debug the issue a bit and observe closer what happens. Unfortunately the slowdown does not occur there. I than closed Visual Studio and it is slow again. I than started up just the Project/File selection screen of VS2019 and it was fast again.
So somebody mind explaining me what is happening here?

[Neumann-A]

As far as I can tell the process hangs in the function

template<class Function>
int wait_and_stream_output(Function&& f) 

at (line 407 in system.process.cpp):

            while (ReadFile(child_stdout, (void*)buf.get(), buffer_size, &bytes_read, nullptr) && bytes_read > 0)
            {
                f(StringView{buf.get(), static_cast<size_t>(bytes_read)});
            }

[Neumann-A]

Seems to be introduced by f7fb56decd9d03cf79a1d23f44daa3a23560b995 @ras0219-msft. Tested a few older vcpkg.exe and only the one from 31.12.2019 in my paraview fork loaded vcvarsall.bat fast/direct. (another one from 12.02.2020 already shows the 200s slowdown)
Running with VS open is always fast.
Running with VS closed is slow after the first retry.
Don't know if it is related to Ctrl+C 'ing vcpkg install

[gvanem]

So somebody mind explaining me what is happening here?

Not even people at Microsoft can explain the mess VisualStudio generates.
AFAICS, the slowdown could be caused by some Telemetry files being uploaded to MS.

[Neumann-A]

Steps to make it slow (will not work if VS is open):
- vcpkg install <anything>
- CTRL+C (SIGINT) while installing
- vcpkg install <anything> <- will be slow

Steps to make it fast:

• open Visual Studio
• or reboot

[NancyLi1013]

@ras0219-msft
Could you help take a look about this?

[pparvi]

This issue is caused by following snippet inside C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\Common7\Tools\VsDevCmd.bat:

@REM Send Telemetry if user's VS is opted-in
if "%VSCMD_SKIP_SENDTELEMETRY%"=="" (
    if "%VSCMD_DEBUG%" NEQ "" (
        @echo [DEBUG:%~nx0] Sending telemetry
        powershell.exe -NoProfile -Command "& {Import-Module '%~dp0\Microsoft.VisualStudio.DevShell.dll'; Send-VsDevShellTelemetry -NewInstanceType Cmd;}"
    ) else (
        START "" /B powershell.exe -NoProfile -Command "& {if($PSVersionTable.PSVersion.Major -ge 3){Import-Module '%~dp0\Microsoft.VisualStudio.DevShell.dll'; Send-VsDevShellTelemetry -NewInstanceType Cmd; }}" > NUL
    )
)

(Seems more like an opt-out...).

And can be worked around by setting following environment variables in the shell before running vcpkg:

set VSCMD_SKIP_SENDTELEMETRY=1
set VCPKG_KEEP_ENV_VARS=VSCMD_SKIP_SENDTELEMETRY

[Neumann-A]

I can confirm that:

set VSCMD_SKIP_SENDTELEMETRY=1
set VCPKG_KEEP_ENV_VARS=VSCMD_SKIP_SENDTELEMETRY

seems to work and is making the vcvarsall.bat call also a bit faster (<1s now). If VCPKG is compiled with -disableMetrics VSCMD_SKIP_SENDTELEMETRY=1 should be set by default by VCPKG in the created environment.

related #8756

[ghost]

I have noticed the same delays on my installed vs2019 instances. The vs2017 instances do not have this issue.
Also, I noted before vs2019 16.5.x vs2019 would compile/link/install quicker than the same ports on vs2017, but since vs2019 16.5.x versions, vs2019 has been considerably slower than vs2017.

[strega-nil]

This seems to be a bug in vcvarsall, not in vcpkg; I've noticed this issue in not-vcpkg as well. I'm not sure what could be the issue; hopefully we can add a cache for this to at least fix it for us, but someone should probably open a developer community issue.

[strega-nil]

We're currently discussing whether it makes sense to always set VSCMD_SKIP_SENDTELEMETRY=1.

[strega-nil]

And we have agreed that it makes sense