timeout during benchmarkdotnet project restore

[frank-dong-ms-zz]

Hi,

We are constantly seeing timeouts during restore of benchmarkdotnet project like below:

` // start dotnet restore /p:Configuration=Release-netcoreapp3_1 --no-dependencies /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 in D:\a\1\s\artifacts\bin\Microsoft.ML.Benchmarks.Tests\Release-netcoreapp3_1\netcoreapp3.1\80eb7cd0-94a4-4eeb-811c-2198ef3272bd // command took more that the timeout: 120s. Killing the process tree! // Done, took 00:02:01 (121.34 sec) // Found 2 benchmarks: // CacheDataViewBench.CacheWithCursor: Dry(Arguments=/p:Configuration=Release-netcoreapp3_1,/p:buildTimeout=600,--no-dependencies, Toolchain=netcoreapp3.1, IterationCount=1, LaunchCount=1, RunStrategy=ColdStart, UnrollFactor=1, WarmupCount=1) // CacheDataViewBench.CacheWithSeeker: Dry(Arguments=/p:Configuration=Release-netcoreapp3_1,/p:buildTimeout=600,--no-dependencies, Toolchain=netcoreapp3.1, IterationCount=1, LaunchCount=1, RunStrategy=ColdStart, UnrollFactor=1, WarmupCount=1)

// Build Error: Standard output:

Standard error: The configured timeout 00:02:00 was reached!

// Build Error: Standard output:

Standard error: The configured timeout 00:02:00 was reached! `

so is this timeout happens during nuget download package or some where else? we are not able to see more details even we set the verbosity to detailed. also, is there any way to increase the timeout?

Thanks.

[adamsitnik]

Hi @frank-dong-ms

so is this timeout happens during nuget download package or some where else?

From the logs that you have provided, it looks that dotnet restore performed by BDN on the auto-generated project takes more than 120s.

Have you changed anything recently that could affect this time? 2 minutes should and afair were always enough for the ML.NET repo.

is there any way to increase the timeout?

The timeout is configurable.

In the case of ML.NET benchmarks, you would have to change the following code:

From:

        private IToolchain CreateToolchain()
        {
#if NETFRAMEWORK
            var tfm = "net461";
            var csProj = CsProjClassicNetToolchain.Net461;
#else
            var tfm = AppDomain.CurrentDomain.GetData("FX_PRODUCT_VERSION") == null ?
                NetCoreAppSettings.NetCoreApp21.TargetFrameworkMoniker : NetCoreAppSettings.NetCoreApp31.TargetFrameworkMoniker;
            var csProj = AppDomain.CurrentDomain.GetData("FX_PRODUCT_VERSION") == null ?
                CsProjCoreToolchain.NetCoreApp21 : CsProjCoreToolchain.NetCoreApp31;
#endif
            return new Toolchain(
                tfm,
                new ProjectGenerator(tfm), // custom generator that copies native dependencies
                csProj.Builder,
                csProj.Executor);
        }

To:

        private IToolchain CreateToolchain()
        {
            TimeSpan timeout = TimeSpan.FromMinutes(2); // current default BDN setting

#if NETFRAMEWORK
            var tfm = "net461";
            var csProj = CsProjClassicNetToolchain.From(tfm, timeout: timeout);
#else
            var settings = AppDomain.CurrentDomain.GetData("FX_PRODUCT_VERSION") == null
                ? NetCoreAppSettings.NetCoreApp21 : NetCoreAppSettings.NetCoreApp31;

            settings = settings.WithTimeout(timeout);

            var tfm = settings.TargetFrameworkMoniker;
            var csProj = CsProjCoreToolchain.From(settings);
#endif
            return new Toolchain(
                tfm,
                new ProjectGenerator(tfm), // custom generator that copies native dependencies
                csProj.Builder,
                csProj.Executor);
        }

[frank-dong-ms-zz]

@adamsitnik Thanks Adam, I tried to increase the timeout and CI are passing.

Have you changed anything recently that could affect this time? 2 minutes should and afair were always enough for the ML.NET repo.

We recently moved our build system from build tools to Arcade and that is the only significant change. I tried to change verbosity option to be detailed to benchmarkdotnet project's msbuild argument and log didn't show anything useful, do you know how can we tell where the time is being spent?

[adamsitnik]

I tried to change verbosity option to be detailed to benchmarkdotnet project's msbuild argument and log didn't show anything useful

How have you done that? Did you modify this line?

do you know how can we tell where the time is being spent

The best way would be to enforce BDN to pass /bl to MSBuild and analyze the produced binary log with https://msbuildlog.com/ and keep the produced artifacts to play with the auto-generated projects without BDN;

You can do that by using [KeepBenchmarkFiles] attribute on the type which defines the benchmarks or by using config.KeepBenchmarkFiles() extension method. More about troubleshooting BDN can be found here

We recently moved our build system from build tools to Arcade and that is the only significant change.

My current best guess is that your previous build tools were not using a custom folder for restoring NuGet packages and Arcade does use it. Then BDN runs a plain dotnet restore without specyfing the path and everything is downloaded one more time (and it takes more than 2 minutes):

It can be set by using this method:

https://github.com/dotnet/BenchmarkDotNet/blob/10abc4f4daa5142f0257c9d512a38afc2ab28be1/src/BenchmarkDotNet/Toolchains/DotNetCli/NetCoreAppSettings.cs#L93-L94