Fix timeout in CriticalSection for large solutions

In MSBuild, building projects in parallel, especially ones with shared
references (e.g. applications referencing the same library), can
potentially create a race condition that leads to build errors
when accessing shared resources. For this reason, we've introduced the
CriticalSection task which uses a system-wide synchronization object to
serialize parts of the build.

Some issues with the CriticalSection task have been reported, namely
that project builds fail with timeout errors while waiting to get access
to the critical section.

A constant timeout value, no matter how long, will eventually fail with
a large enough solution. To work around this issue, acquiring the
critical section lock will now use an adjustable timeout window,
relative to the time of the most recent lock release.

The following auto-tests are included:

== Test_CriticalSection

 * FailByRaceConditionAsync: sanity check; start 100 unsynced background
   tasks in parallel and observe race condition. Expected to fail.

 * FailByTimeoutAsync: start 100 tasks synchronized by CriticalSection,
   with 10 secs timeout and 1 sec of work. Expected to fail due to
   timeout while waiting to acquire lock.

 * SerializedWorkAsync: start 100 tasks synchronized by CriticalSection,
   with 1 sec of work and 10 secs timeout calculated from the time of
   the most recent lock release.

== Test_BigSolution

 * BigSolution_FailByTimeout: succeed in building a solution with 2
   projects, but then fail to build a solution with 100 projects, due to
   timeout waiting for the critical section lock. Expected to fail.

 * BigSolution_TimeoutAdjustment: build a solution with 100 projects,
   with 10 secs timeout calculated calculated from the time of the most
   recent lock release.

Fixes: QTVSADDINBUG-921
Change-Id: Ie803c220afc1226a59b1af69d4b4318f6c8ea80b
Reviewed-by: Karsten Heimrich <karsten.heimrich@qt.io>

7 files changed, 244 insertions, 37 deletions

diff --git a/QtMSBuild/QtMsBuild/qt.targets b/QtMSBuild/QtMsBuild/qt.targets
index e9c1cffe..ef1952d2 100644
--- a/QtMSBuild/QtMsBuild/qt.targets
+++ b/QtMSBuild/QtMsBuild/qt.targets
@@ -37,6 +37,19 @@
 
   <!--
   /////////////////////////////////////////////////////////////////////////////////////////////////
+  // Defaults for CriticalSection task
+  // -->
+  <PropertyGroup>
+    <QtCriticalSectionTimeout Condition="'$(QtCriticalSectionTimeout)' == ''"
+      >10</QtCriticalSectionTimeout>
+    <QtCriticalSectionFixedTimeout Condition="'$(QtCriticalSectionFixedTimeout)' == ''"
+      >false</QtCriticalSectionFixedTimeout>
+    <QtCriticalSectionDelay Condition="'$(QtCriticalSectionDelay)' == ''"
+      >0</QtCriticalSectionDelay>
+  </PropertyGroup>
+
+  <!--
+  /////////////////////////////////////////////////////////////////////////////////////////////////
   // Qt Variables Expansion
   // -->
   <PropertyGroup Condition="'$(QtVsProjectSettings)' == 'true'">
diff --git a/QtMSBuild/QtMsBuild/qt_globals.targets b/QtMSBuild/QtMsBuild/qt_globals.targets
index e98dc2a9..564a75dd 100644
--- a/QtMSBuild/QtMsBuild/qt_globals.targets
+++ b/QtMSBuild/QtMsBuild/qt_globals.targets
@@ -130,7 +130,8 @@
     BeforeTargets="QtWorkPrepare">
 
     <Message Importance="High" Condition="'$(QtDebug)' == 'true'" Text="#### QtPrepare"/>
-    <CriticalSection Lock="true" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="true" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
 
     <ReadLinesFromFile File="$(QtLogFilePath)">
       <Output TaskParameter="Lines" ItemName="QtLogData"/>
@@ -678,7 +679,8 @@
   <Target
     Name="Qt"
     DependsOnTargets="QtPrepare;QtWork;QtSetAdditionalOptions">
-    <CriticalSection Lock="false" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="false" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
     <OnError ExecuteTargets="QtLeaveCriticalSection_OnError"/>
   </Target>
 
@@ -689,10 +691,12 @@
   // Synchronize calls to InitializeBuildStatus
   // -->
   <Target Name="QtEnterCriticalSection_InitializeBuildStatus" BeforeTargets="InitializeBuildStatus">
-    <CriticalSection Lock="true" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="true" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
   </Target>
   <Target Name="QtLeaveCriticalSection_InitializeBuildStatus" AfterTargets="InitializeBuildStatus">
-    <CriticalSection Lock="false" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="false" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
   </Target>
   <PropertyGroup>
     <!--// Schedule critical section enter/leave targets around InitializeBuildStatus -->
@@ -716,10 +720,12 @@
   // Synchronize calls to FinalizeBuildStatus
   // -->
   <Target Name="QtEnterCriticalSection_FinalizeBuildStatus" BeforeTargets="FinalizeBuildStatus">
-    <CriticalSection Lock="true" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="true" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
   </Target>
   <Target Name="QtLeaveCriticalSection_FinalizeBuildStatus" AfterTargets="FinalizeBuildStatus">
-    <CriticalSection Lock="false" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="false" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
   </Target>
   <PropertyGroup>
     <!--// Schedule critical section enter/leave targets around FinalizeBuildStatus -->
@@ -743,7 +749,8 @@
   // Fail-safe release of critical section lock, to be used in OnError tasks
   // -->
   <Target Name="QtLeaveCriticalSection_OnError">
-    <CriticalSection Lock="false" Name="$(ProjectGuid)" />
+    <CriticalSection Lock="false" Name="$(ProjectGuid)" Timeout="$(QtCriticalSectionTimeout)"
+      FixedTimeout="$(QtCriticalSectionFixedTimeout)" Delay="$(QtCriticalSectionDelay)" />
   </Target>
 
   <!--
diff --git a/QtMSBuild/Tasks/CriticalSection.cs b/QtMSBuild/Tasks/CriticalSection.cs
index e22c7197..dc8acd66 100644
--- a/QtMSBuild/Tasks/CriticalSection.cs
+++ b/QtMSBuild/Tasks/CriticalSection.cs
@@ -34,50 +34,56 @@ namespace QtVsTools.QtMsBuild.Tasks
         public static bool Execute(
         #region Parameters
             System.Boolean Lock,
-            System.String Name)
+            System.String Name,
+            System.Int32 Timeout = 0,
+            System.Boolean FixedTimeout = false,
+            System.Int32 Delay = 0)
         #endregion
         {
             #region Code
             var buildEngine = BuildEngine as IBuildEngine4;
+            Name = Name.Trim(' ', '{', '}');
+            var tmpFile = Path.Combine(Path.GetTempPath(), string.Format("qtmsbuild{0}.tmp", Name));
 
-            // Acquire lock
-            string lockName = string.Format("Global\\{0}", Name);
-            EventWaitHandle buildLock = null;
-            if (!EventWaitHandle.TryOpenExisting(lockName, out buildLock)) {
+            if (Timeout <= 0)
+                Timeout = 10;
+
+            var eventName = string.Format("Global\\QtMSBuild.Lock.Project-{0}", Name);
+            var waitHandle = buildEngine.GetRegisteredTaskObject(eventName,
+                RegisteredTaskObjectLifetime.Build) as EventWaitHandle;
+            if (waitHandle == null && !EventWaitHandle.TryOpenExisting(eventName, out waitHandle)) {
                 // Lock does not exist; create lock
                 bool lockCreated;
-                buildLock = new EventWaitHandle(
-                    true, EventResetMode.AutoReset, lockName, out lockCreated);
+                waitHandle = new EventWaitHandle(
+                    true, EventResetMode.AutoReset, eventName, out lockCreated);
                 if (lockCreated) {
                     // Keep lock alive until end of build
                     buildEngine.RegisterTaskObject(
-                        Name, buildLock, RegisteredTaskObjectLifetime.Build, false);
+                        eventName, waitHandle, RegisteredTaskObjectLifetime.Build, false);
                 }
             }
-            if (buildLock == null) {
-                Log.LogError("Qt::BuildLock[{0}]: Error accessing lock", Name);
-                return false;
+
+            if (!Lock) {
+                if (!FixedTimeout)
+                    File.WriteAllBytes(tmpFile, new byte[0]);
+                if (Delay > 0)
+                    Thread.Sleep(Delay);
+                waitHandle.Set();
+                return true;
             }
-            if (Lock) {
-                // Wait until locked
-                if (!buildLock.WaitOne(1000)) {
-                    var t = Stopwatch.StartNew();
-                    do {
-                        // Check for build errors
-                        if (Log.HasLoggedErrors) {
-                            Log.LogError("Qt::BuildLock[{0}]: Errors logged; wait aborted", Name);
-                            return false;
-                        }
-                        // Timeout after 10 secs.
-                        if (t.ElapsedMilliseconds >= 10000) {
-                            Log.LogError("Qt::BuildLock[{0}]: Timeout; wait aborted", Name);
-                            return false;
-                        }
-                    } while (!buildLock.WaitOne(1000));
+
+            var timeoutReference = DateTime.Now;
+            while (!waitHandle.WaitOne(3000)) {
+                if (Log.HasLoggedErrors) {
+                    Log.LogError("Qt::BuildLock[{0}]: Errors logged; wait aborted", Name);
+                    return false;
+                }
+                if (!FixedTimeout && File.Exists(tmpFile))
+                    timeoutReference = File.GetLastWriteTime(tmpFile);
+                if (DateTime.Now.Subtract(timeoutReference).TotalSeconds >= Timeout) {
+                    Log.LogError("Qt::BuildLock[{0}]: Timeout; wait aborted", Name);
+                    return false;
                 }
-            } else {
-                // Unlock
-                buildLock.Set();
             }
             #endregion
 
diff --git a/Tests/Test_QtMsBuild.Build/Test_BigSolution.cs b/Tests/Test_QtMsBuild.Build/Test_BigSolution.cs
new file mode 100644
index 00000000..d329cda5
--- /dev/null
+++ b/Tests/Test_QtMsBuild.Build/Test_BigSolution.cs
@@ -0,0 +1,57 @@
+/***************************************************************************************************
+ Copyright (C) 2023 The Qt Company Ltd.
+ SPDX-License-Identifier: LicenseRef-Qt-Commercial OR LGPL-3.0-only OR GPL-2.0-only OR GPL-3.0-only
+***************************************************************************************************/
+
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.Build.Construction;
+using Microsoft.Build.Execution;
+using Microsoft.VisualStudio.TestTools.UnitTesting;
+using Microsoft.VisualStudio.Workspace.Build;
+
+namespace QtVsTools.Test.QtMsBuild.Build
+{
+    [TestClass]
+    public class Test_BigSolution
+    {
+        private bool Build(int count, bool fixedTimeout = false, int delay = -1, int timeout = -1)
+        {
+            using var temp = new TempProject();
+            temp.GenerateBigSolution(
+                $@"{Properties.SolutionDir}Tests\BigSolution\template", count);
+            return MsBuild.Run(temp.ProjectDir,
+                $"-p:QtMsBuild={Path.Combine(Environment.CurrentDirectory, "QtMsBuild")}",
+                timeout >= 0 ? $"-p:QtCriticalSectionTimeout={timeout}" : null,
+                fixedTimeout ? "-p:QtCriticalSectionFixedTimeout=true" : null,
+                delay >= 0 ? $"-p:QtCriticalSectionDelay={delay}" : null,
+                "-p:Platform=x64", "-p:Configuration=Release",
+                "-m", "-t:Build", temp.ProjectFileName);
+        }
+
+        [TestMethod]
+        public void BigSolution_FailByTimeout()
+        {
+            if (Properties.Configuration == "Release")
+                Assert.Inconclusive("Disabled in the 'Release' configuration.");
+
+            Assert.IsTrue(Build(2, true, 1000));
+
+            if (Build(100, true, 1000))
+                Assert.Inconclusive();
+        }
+
+        [TestMethod]
+        public void BigSolution_TimeoutAdjustment()
+        {
+            if (Properties.Configuration == "Release")
+                Assert.Inconclusive("Disabled in the 'Release' configuration.");
+
+            Assert.IsTrue(Build(100));
+        }
+    }
+}
diff --git a/Tests/Test_QtMsBuild.Build/Test_QtMsBuild.Build.csproj b/Tests/Test_QtMsBuild.Build/Test_QtMsBuild.Build.csproj
index 26ec1a66..882b4ee9 100644
--- a/Tests/Test_QtMsBuild.Build/Test_QtMsBuild.Build.csproj
+++ b/Tests/Test_QtMsBuild.Build/Test_QtMsBuild.Build.csproj
@@ -110,6 +110,7 @@
     <Compile Include="Properties\AssemblyInfo.cs" />
     <Compile Include="Logger.cs" />
     <Compile Include="MsBuild.cs" />
+    <Compile Include="Test_BigSolution.cs" />
     <Compile Include="Test_IntDir.cs" />
     <Compile Include="Test_LateBinding.cs" />
     <Compile Include="Test_Eval.cs" />
diff --git a/Tests/Test_QtMsBuild.Tasks/Test_CriticalSection.cs b/Tests/Test_QtMsBuild.Tasks/Test_CriticalSection.cs
new file mode 100644
index 00000000..2abfab90
--- /dev/null
+++ b/Tests/Test_QtMsBuild.Tasks/Test_CriticalSection.cs
@@ -0,0 +1,116 @@
+/***************************************************************************************************
+ Copyright (C) 2023 The Qt Company Ltd.
+ SPDX-License-Identifier: LicenseRef-Qt-Commercial OR LGPL-3.0-only OR GPL-2.0-only OR GPL-3.0-only
+***************************************************************************************************/
+
+using System.Linq;
+using System.Collections.Concurrent;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.VisualStudio.TestTools.UnitTesting;
+
+namespace QtVsTools.Test.QtMsBuild.Tasks
+{
+    using QtVsTools.QtMsBuild.Tasks;
+
+    [TestClass]
+    public class Test_CriticalSection
+    {
+        private const string LockName = "TEST_CRITICAL_SECTION";
+        private int WorkerCount { get; set; }
+        private int WorkDuration { get; set; }
+        private int TimeoutSecs { get; set; }
+        private bool SerializedWork { get; set; }
+        private bool FixedTimeout { get; set; }
+        private MockBuildEngine BuildEngine { get; set; } = new();
+        private MockTaskLogger Logger { get; set; } = new();
+
+        [TestInitialize]
+        public void TestInitialize()
+        {
+            WorkerCount = 100;
+            WorkDuration = 1000;
+            SerializedWork = true;
+            TimeoutSecs = 10;
+            FixedTimeout = false;
+            CriticalSection.BuildEngine = BuildEngine;
+            CriticalSection.Log = Logger;
+        }
+
+        [TestCleanup]
+        public void TestCleanup()
+        {
+            if (SerializedWork)
+                CriticalSection.Execute(false, LockName);
+            BuildEngine.ResetTaskObjects();
+            Workers = new();
+        }
+
+        [TestMethod]
+        public async Task FailByRaceConditionAsync()
+        {
+            if (Properties.Configuration == "Release")
+                Assert.Inconclusive("Disabled in the 'Release' configuration.");
+            SerializedWork = false;
+            if (await DoWorkAsync())
+                Assert.Inconclusive();
+        }
+
+        [TestMethod]
+        public async Task FailByTimeoutAsync()
+        {
+            if (Properties.Configuration == "Release")
+                Assert.Inconclusive("Disabled in the 'Release' configuration.");
+            FixedTimeout = true;
+            if (await DoWorkAsync())
+                Assert.Inconclusive();
+        }
+
+        [TestMethod]
+        public async Task SerializedWorkAsync()
+        {
+            if (Properties.Configuration == "Release")
+                Assert.Inconclusive("Disabled in the 'Release' configuration.");
+            Assert.IsTrue(await DoWorkAsync());
+        }
+
+        private async Task<bool> DoWorkAsync()
+        {
+            var tasks = Enumerable.Range(1, WorkerCount)
+                .Select(workerId => Task<bool>.Factory.StartNew(() =>
+                {
+                    if (SerializedWork && !EnterCriticalSection())
+                        return false;
+                    var result = DoWork(workerId);
+                    if (SerializedWork)
+                        LeaveCriticalSection();
+                    return result;
+                },
+                CancellationToken.None, TaskCreationOptions.None, TaskScheduler.Default));
+            var taskResults = await Task.WhenAll(tasks);
+            return taskResults.All(result => result == true);
+        }
+
+        private bool EnterCriticalSection()
+        {
+            return CriticalSection.Execute(true, LockName, TimeoutSecs, FixedTimeout);
+        }
+
+        private void LeaveCriticalSection()
+        {
+            CriticalSection.Execute(false, LockName);
+        }
+
+        private ConcurrentBag<int> Workers { get; set; } = new();
+
+        private bool DoWork(int id)
+        {
+            if (Workers.Count > 0)
+                return false;
+            Workers.Add(id);
+            Thread.Sleep(WorkDuration);
+            Workers.TryTake(out _);
+            return true;
+        }
+    }
+}
diff --git a/Tests/Test_QtMsBuild.Tasks/Test_QtMsBuild.Tasks.csproj b/Tests/Test_QtMsBuild.Tasks/Test_QtMsBuild.Tasks.csproj
index d0eae0eb..97b44692 100644
--- a/Tests/Test_QtMsBuild.Tasks/Test_QtMsBuild.Tasks.csproj
+++ b/Tests/Test_QtMsBuild.Tasks/Test_QtMsBuild.Tasks.csproj
@@ -98,10 +98,17 @@
     <Compile Include="MockBuildEngine.cs" />
     <Compile Include="MockTaskLogger.cs" />
     <Compile Include="Test_GetVarsFromMSBuild.cs" />
+    <Compile Include="Test_CriticalSection.cs" />
     <Compile Include="Test_Join.cs" />
     <Compile Include="Test_QtRunTask.cs" />
   </ItemGroup>
+  <ItemGroup>
+    <Compile Include="$(SolutionDir)\EvalProps.cs">
+      <Link>EvalProps.cs</Link>
+    </Compile>
+  </ItemGroup>
   <Import Project="$(VSToolsPath)\TeamTest\Microsoft.TestTools.targets" Condition="Exists('$(VSToolsPath)\TeamTest\Microsoft.TestTools.targets')" />
   <Import Project="$(MSBuildToolsPath)\Microsoft.CSharp.targets" />
   <Import Project="$(SolutionDir)\transform.targets" />
+  <Import Condition="Exists('$(SolutionDir)\EvalProps.targets')" Project="$(SolutionDir)\EvalProps.targets" />
 </Project>
\ No newline at end of file