Fix TraceEngine file contention deadlock in multithreaded mode#19
Closed
JanProvaznik wants to merge 7 commits intomainfrom
Closed
Fix TraceEngine file contention deadlock in multithreaded mode#19JanProvaznik wants to merge 7 commits intomainfrom
JanProvaznik wants to merge 7 commits intomainfrom
Conversation
… to avoid resize allocations (dotnet#13377)
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
dotnet#13409) ### Context The VS repo no longer uses `rel/dX.Y` target branches. All insertions from `main` and `vs*` servicing branches should target `main` in VS. The `AutoInsertTargetBranch` had a ~30-line conditional mapping each `vsX.Y` → `rel/dX.Y` that is now dead code. ### Changes Made **`vs-insertion.yml`:** - Replace `AutoInsertTargetBranch` conditional chain with `value: 'main'` — auto always targets main - Trim `TargetBranch` parameter to `auto`/`main`/`rel/insiders`/`rel/stable` - Keep `vs*` resource trigger (MSBuild still has those branches) - Remove obsolete `InsertPackagePropsValues` conditional for old servicing branches (17.x `Microsoft.Build.Engine`/`Conversion.Core` additions, 17.10/17.12/17.14 PackageProps logic) **`vs-insertion-experimental.yml`:** - Trim `TargetBranch` parameter to `main`/`rel/insiders`/`rel/stable` - Remove `exp/vsX.Y` regex detection — auto-triggered builds always target `main` ### Testing Pipeline YAML only — no code changes. ### Notes The `$props` array construction is retained even though `InsertPackagePropsValues` is always unset, in case it's needed for future servicing. --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: JanProvaznik <25267098+JanProvaznik@users.noreply.github.com> Co-authored-by: MichalPavlik <michalpavlik@outlook.com> Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
Related to dotnet#12867 ### Context Fixing two bugs in telemetry infrastructure when using /m /mt (in-proc multithreaded) mode: **Thread-safety crash**: all in-proc nodes share a single TelemetryForwarderProvider singleton. Multiple RequestBuilder instances run on dedicated threads and call AddTask/AddTarget concurrently on the same WorkerNodeTelemetryData dictionary fields, causing race conditions and dictionary corruption. **Nx telemetry duplication**: In /m /mt mode, N BuildRequestEngine instances share one TelemetryForwarderProvider singleton. Each engine calls FinalizeProcessing on shutdown, sending the entire accumulated data each time. The InternalTelemetryConsumingLogger merges all N copies, inflating every counter N times. Reproduction: 20+ non-SDK .NET Framework library projects + 1 exe referencing all of them, built with MSBuild.exe Repro.sln /m /mt. ### Changes Made Fix **Batch-then-merge** in RequestBuilder: Each RequestBuilder now accumulates task/target telemetry into a local WorkerNodeTelemetryData instance (zero contention), then merges once into the shared state via elemetryForwarder.MergeWorkerData(). **Thread-safe TelemetryForwarder**: Added an internal lock protecting both MergeWorkerData and FinalizeProcessing. The forwarder is a singleton shared across BuildRequestEngine instances in /m /mt mode, so concurrent access is expected. **Swap-and-send in FinalizeProcessing**: Instead of sending the same accumulated data on every call, FinalizeProcessing atomically swaps the internal data with a fresh empty instance under the lock, then sends only if non-empty. This ensures: - First engine to finalize sends all data accumulated so far - Subsequent engines find empty data and skip sending (no duplication) - Late merges from other engines go into the new instance and are sent by the next FinalizeProcessing call (no data loss) ### Testing Locally tested that the issue is gone on a repro project. Unit tests
) ## Fix for dotnet#13188: MT mode ResultsNodeId race condition ### Problem In MT (multi-threaded) mode, builds intermittently crash with: \\\ InternalErrorException: MSB0001: Internal MSBuild Error: Results for configuration X were not retrieved from node Y \\\ ### Root Cause \BuildRequestConfiguration.ResultsNodeId\ is a single \int\ field shared by all in-proc nodes via the shared \ConfigCache\. When multiple in-proc nodes simultaneously need a configuration's results, they race through \HandleRequestBlockedOnResultsTransfer\, which unconditionally overwrites \ResultsNodeId\ to the requesting node's ID. The last writer wins, causing other waiters to find a mismatched value when they wake up, failing the assertion in \RequestBuilder.BuildProject()\. ### Key Insight **In MT mode, the entire results transfer mechanism is unnecessary.** All in-proc nodes share the same \ConfigCache\ and \ResultsCache\ by reference. When a config is built on any node, the results are immediately accessible to all other in-proc nodes through the shared cache. MT mode also disallows out-of-proc nodes (\Scheduler.cs\ sets OOP node count to 0 when \MultiThreaded=true\), so there are no cross-process transfers to worry about. ### Fix Extracted the transfer-needed check into a testable \NeedsResultsTransfer\ method that returns \ alse\ when \MultiThreaded\ mode is active, skipping the entire transfer block. ### Tests - **Unit test (red/green validated)**: \NeedsResultsTransfer_SkipsInMultiThreadedMode\ — 6 Theory cases covering all MT/ST × node ID combinations. Confirmed: fails without fix, passes with fix. - **Integration test**: \MultiThreadedBuild_SharedConfiguration_DoesNotCrash\ — 8 parallel projects referencing same dependency with different target sets, forcing cache misses that exercise the transfer code path. ### No ChangeWave Needed This is a crash fix, not a behavioral change. The transfer was already a no-op in MT mode (copying data between shared references). Skipping it produces identical build results while preventing the race condition crash. Fixes dotnet#13188 ---------
In multithreaded (-mt) mode, multiple in-proc node engines run in the
same process. Each engine's TraceEngine() method wrote to the same
EngineTrace_{PID}.txt file with FileShare.Read. When two engines traced
concurrently, the second got an IOException, which propagated through
QueueAction's error handler and fatally crashed the ActionBlock work
queue. All subsequent Post() calls were silently rejected, causing
request completions to be dropped and the scheduler to deadlock.
Fix:
- Use per-node trace files: EngineTrace_{PID}_{NodeId}.txt
- Catch IOException in TraceEngine so trace failures can never crash
the build engine
Added regression test that enables MSBUILDDEBUGSCHEDULER=1 during a
multithreaded build with parallel child projects.
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
JanProvaznik
pushed a commit
that referenced
this pull request
Mar 27, 2026
…tInMetadata performance (dotnet#13386) I recommend reviewing this pull request commit-by-commit. # Summary of Changes - Introduce new MSBuild.Benchmarks project for tackling performance investigations. - Add a few benchmarks for various methods on `ItemSpecModifiers`. - Make several performance fixes related to `ItemSpecModifiers` and `BuildInMetadata`. - General clean up. Across the board, most benchmarks are **3×–35× faster** with **allocations eliminated or reduced by 93–100%**. The largest wins are in repeated-access and multi-item scenarios, which are the most representative of real build workloads. The full details are below but here are the highlights. ## Highlights ### 🚀 Speed Improvements (.NET 10.0) | Benchmark | Before | After | Speedup | |---|---|---|---| | `IsItemSpecModifier_AllModifiers` | 151.4 ns | 38.5 ns | **3.9×** | | `GetItemSpecModifier_DefiningProjectDirectory` | 812.2 ns | 72.4 ns | **11.2×** | | `TaskItem_AllDerivableModifiers_Once` | 434.5 ns | 87.4 ns | **5.0×** | | `TaskItem_FilenameAndExtension_Repeated` | 908.5 ns | 173.7 ns | **5.2×** | | `TaskItem_Filename_ManyItems` | 9,651 ns | 1,857 ns | **5.2×** | | `TaskItem_FullPathDerivedModifiers_Repeated` | 2,128 ns | 321.6 ns | **6.6×** | | `TaskItem_DefiningProjectDirectory_Repeated` | 9,121 ns | 970.8 ns | **9.4×** | | `PI_DefiningProjectDirectory_Repeated` | 9,092 ns | 1,021 ns | **8.9×** | | `PI_DefiningProjectFullPath_AllItems_Multi` | 35,245 ns | 9,947 ns | **3.5×** | | `PI_DefiningProjectDir_AllItems_Multi_Repeated` | 878,931 ns | 103,961 ns | **8.5×** | | `PI_FilenameExtension_AllItems` | 22,698 ns | 5,343 ns | **4.2×** | | `PI_FilenameExtension_AllItems_Repeated` | 181,612 ns | 67,028 ns | **2.7×** | ### 🧹 Allocation Reductions (.NET 10.0) | Benchmark | Before | After | Reduction | |---|---|---|---| | `TaskItem_AllDerivableModifiers_Once` | 1,232 B | **0 B** | 100% | | `TaskItem_FilenameAndExtension_Repeated` | 640 B | **0 B** | 100% | | `TaskItem_Filename_ManyItems` | 7,920 B | **0 B** | 100% | | `TaskItem_FullPathDerivedModifiers_Repeated` | 7,120 B | **0 B** | 100% | | `TaskItem_DefiningProjectDirectory_Repeated` | 8,240 B | **0 B** | 100% | | `TaskItem_AllDefiningProjectModifiers_Once` | 912 B | **0 B** | 100% | | `TaskItem_DefiningProjectNameExtension_AllItems` | 8,800 B | **0 B** | 100% | | `GetItemSpecModifier_DefiningProjectDirectory` | 536 B | **0 B** | 100% | | `PI_FilenameExtension_AllItems_Repeated` | 143,840 B | **640 B** | 99.6% | | `PI_DefiningProjectDir_AllItems_Multi_Repeated` | 824,640 B | **640 B** | 99.9% | | `PI_FilenameExtension_AllItems` | 14,384 B | **64 B** | 99.6% | | `PI_DefiningProjectDirectory_Repeated` | 8,304 B | **64 B** | 99.2% | | `PI_AllDerivableModifiers_Once` | 1,296 B | **64 B** | 95.1% | | `PI_AllDefiningProjectModifiers_Once` | 976 B | **64 B** | 93.4% | ### 📊 .NET Framework 4.8.1 | Benchmark | Before | After | Speedup | |---|---|---|---| | `GetItemSpecModifier_DefiningProjectDirectory` | 5,467 ns | 156.8 ns | **34.9×** | | `TaskItem_DefiningProjectDirectory_Repeated` | 58,025 ns | 2,539 ns | **22.9×** | | `PI_DefiningProjectDir_AllItems_Multi_Repeated` | 6,399 μs | 282.3 μs | **22.7×** | | `TaskItem_Filename_ManyItems` | 110,078 ns | 6,916 ns | **15.9×** | | `TaskItem_FullPathDerivedModifiers_Repeated` | 26,619 ns | 2,262 ns | **11.8×** | | `PI_FilenameExtension_AllItems_Repeated` | 2,162 μs | 202.6 μs | **10.7×** | | `TaskItem_AllDerivableModifiers_Once` | 5,322 ns | 507.2 ns | **10.5×** | | `PI_FilenameExtension_AllItems` | 216,406 ns | 20,366 ns | **10.6×** | | `TaskItem_FilenameAndExtension_Repeated` | 10,238 ns | 664.7 ns | **15.4×** | | `PI_AllDerivableModifiers_Once` | 5,525 ns | 688.6 ns | **8.0×** | | `PI_DefiningProjectDirectory_Repeated` | 64,204 ns | 2,796 ns | **23.0×** | | `PI_AllDefiningProjectModifiers_Once` | 9,808 ns | 1,154 ns | **8.5×** | | `TaskItem_AllDefiningProjectModifiers_Once` | 8,636 ns | 965.3 ns | **8.9×** | ## 'Quick-and-Dirty' Telemetry I had Copilot write some "quick-and-dirty" telemetry to track information in `ItemSpecModifiers` and dump it to a file. I built MSBuild with that extra telemetry and then built Roslyn (starting from `Microsoft.VisualStudio.LanguageServices.CSharp.csproj`) using that MSBuild. This gave me a dump with loads of interesting details. For example, `IsItemSpecModifier` was called 901,057 times. <details> <summary><b>Full Quick-and-Dirty Telemetry Dump</b></summary> ``` === ItemSpecModifiers Telemetry (2026-03-12T09:38:41.0365991-07:00) === --- Top-level method calls --- IsItemSpecModifier: 901,057 IsDerivableItemSpecModifier: 144,857 GetItemSpecModifier: 180,890 --- Compute helper calls --- ComputeFullPath: 75,443 ComputeRootDir: 84 ComputeFilename: 57,426 ComputeExtension: 32,071 ComputeRelativeDir: 22 ComputeDirectory: 84 ComputeModifiedTime: 0 ComputeCreatedTime: 0 ComputeAccessedTime: 0 --- Per-modifier breakdown (inside GetItemSpecModifier) --- FullPath: 44,783 RootDir: 41 Filename: 57,426 Extension: 6,462 RelativeDir: 22 Directory: 41 RecursiveDir: 0 Identity: 15,814 ModifiedTime: 0 CreatedTime: 0 AccessedTime: 0 DefiningProjectFullPath: 30,535 DefiningProjectDirectory: 43 DefiningProjectName: 0 DefiningProjectExtension: 25,609 ========================================================== Per-ItemSpec Modifier Hit Matrix ========================================================== Unique item specs seen: 13,809 Item specs hit > 1 time: 13,005 Grand total modifier lookups: 180,890 --- Top 50 hottest item specs (by total modifier calls) --- #1 (1,502 calls): System.Runtime.CompilerServices.InternalsVisibleTo Identity 751 DefiningProjectFullPath 751 #2 (380 calls): D:\Projects\roslyn\artifacts\bin\Microsoft.CodeAnalysis\Debug\netstandard2.0\Microsoft.CodeAnalysis.dll FullPath 17 Filename 280 Extension 40 Identity 21 DefiningProjectFullPath 22 #3 (270 calls): D:\Projects\roslyn\artifacts\bin\Microsoft.CodeAnalysis.Scripting\Debug\netstandard2.0\Microsoft.CodeAnalysis.Scripting.dll FullPath 12 Filename 195 Extension 30 Identity 16 DefiningProjectFullPath 17 #4 (270 calls): D:\Projects\roslyn\artifacts\bin\Microsoft.CodeAnalysis.Workspaces\Debug\netstandard2.0\Microsoft.CodeAnalysis.Workspaces.dll FullPath 12 Filename 195 Extension 30 Identity 16 DefiningProjectFullPath 17 #5 (247 calls): D:\.nuget\packages\system.threading.tasks.extensions\4.6.3\lib\netstandard2.0\System.Threading.Tasks.Extensions.dll FullPath 13 Filename 221 Identity 13 #6 (247 calls): D:\.nuget\packages\system.memory\4.6.3\lib\netstandard2.0\System.Memory.dll FullPath 13 Filename 221 Identity 13 #7 (247 calls): D:\.nuget\packages\system.buffers\4.6.1\lib\netstandard2.0\System.Buffers.dll FullPath 13 Filename 221 Identity 13 #8 (247 calls): D:\.nuget\packages\system.numerics.vectors\4.6.1\lib\netstandard2.0\System.Numerics.Vectors.dll FullPath 13 Filename 221 Identity 13 #9 (247 calls): D:\.nuget\packages\system.text.encoding.codepages\8.0.0\lib\netstandard2.0\System.Text.Encoding.CodePages.dll FullPath 13 Filename 221 Identity 13 #10 (247 calls): D:\.nuget\packages\system.runtime.compilerservices.unsafe\6.1.2\lib\netstandard2.0\System.Runtime.CompilerServices.Unsafe.dll FullPath 13 Filename 221 Identity 13 #11 (245 calls): D:\.nuget\packages\microsoft.dotnet.arcade.sdk\10.0.0-beta.26160.1\tools\Assets\DotNetPackageIcon.png FullPath 48 Filename 40 Extension 70 Identity 2 DefiningProjectFullPath 37 DefiningProjectDirectory 8 DefiningProjectExtension 40 #12 (245 calls): D:\Projects\roslyn\eng\targets\..\..\src\NuGet\ThirdPartyNotices.rtf FullPath 48 Filename 40 Extension 70 Identity 2 DefiningProjectFullPath 37 DefiningProjectDirectory 8 DefiningProjectExtension 40 #13 (240 calls): D:\.nuget\packages\system.collections.immutable\10.0.1\lib\netstandard2.0\System.Collections.Immutable.dll FullPath 12 Filename 216 Identity 12 #14 (240 calls): D:\.nuget\packages\system.reflection.metadata\10.0.1\lib\netstandard2.0\System.Reflection.Metadata.dll FullPath 12 Filename 216 Identity 12 #15 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Web.dll FullPath 13 Filename 208 Identity 13 #16 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Threading.ThreadPool.dll FullPath 13 Filename 208 Identity 13 #17 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.FileSystem.Watcher.dll FullPath 13 Filename 208 Identity 13 #18 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Resources.ResourceManager.dll FullPath 13 Filename 208 Identity 13 #19 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.dll FullPath 13 Filename 208 Identity 13 dotnet#20 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.Pipes.dll FullPath 13 Filename 208 Identity 13 dotnet#21 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.MemoryMappedFiles.dll FullPath 13 Filename 208 Identity 13 dotnet#22 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.ValueTuple.dll FullPath 13 Filename 208 Identity 13 dotnet#23 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Console.dll FullPath 13 Filename 208 Identity 13 dotnet#24 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Linq.Parallel.dll FullPath 13 Filename 208 Identity 13 dotnet#25 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Security.Claims.dll FullPath 13 Filename 208 Identity 13 dotnet#26 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.UnmanagedMemoryStream.dll FullPath 13 Filename 208 Identity 13 dotnet#27 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Threading.Overlapped.dll FullPath 13 Filename 208 Identity 13 dotnet#28 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Drawing.Primitives.dll FullPath 13 Filename 208 Identity 13 dotnet#29 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Net.WebSockets.dll FullPath 13 Filename 208 Identity 13 dotnet#30 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Security.Cryptography.Algorithms.dll FullPath 13 Filename 208 Identity 13 dotnet#31 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.FileSystem.DriveInfo.dll FullPath 13 Filename 208 Identity 13 dotnet#32 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Diagnostics.Tracing.dll FullPath 13 Filename 208 Identity 13 dotnet#33 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Linq.Expressions.dll FullPath 13 Filename 208 Identity 13 dotnet#34 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Security.Principal.dll FullPath 13 Filename 208 Identity 13 dotnet#35 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Globalization.Calendars.dll FullPath 13 Filename 208 Identity 13 dotnet#36 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Security.Cryptography.Primitives.dll FullPath 13 Filename 208 Identity 13 dotnet#37 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.ObjectModel.dll FullPath 13 Filename 208 Identity 13 dotnet#38 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Xml.XDocument.dll FullPath 13 Filename 208 Identity 13 dotnet#39 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Collections.dll FullPath 13 Filename 208 Identity 13 dotnet#40 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.ComponentModel.TypeConverter.dll FullPath 13 Filename 208 Identity 13 dotnet#41 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Runtime.InteropServices.dll FullPath 13 Filename 208 Identity 13 dotnet#42 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Collections.Concurrent.dll FullPath 13 Filename 208 Identity 13 dotnet#43 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Collections.Specialized.dll FullPath 13 Filename 208 Identity 13 dotnet#44 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Dynamic.Runtime.dll FullPath 13 Filename 208 Identity 13 dotnet#45 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Net.Requests.dll FullPath 13 Filename 208 Identity 13 dotnet#46 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Security.Cryptography.X509Certificates.dll FullPath 13 Filename 208 Identity 13 dotnet#47 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Net.dll FullPath 13 Filename 208 Identity 13 dotnet#48 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.IO.Compression.ZipFile.dll FullPath 13 Filename 208 Identity 13 dotnet#49 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Xml.XmlSerializer.dll FullPath 13 Filename 208 Identity 13 dotnet#50 (234 calls): D:\.nuget\packages\netstandard.library\2.0.3\build\netstandard2.0\ref\System.Runtime.CompilerServices.VisualC.dll FullPath 13 Filename 208 Identity 13 --- Repetition histogram (total modifier calls per item spec → count of item specs) --- 1,502 calls → 1 item specs 380 calls → 1 item specs 270 calls → 2 item specs 247 calls → 6 item specs 245 calls → 2 item specs 240 calls → 2 item specs 234 calls → 112 item specs 226 calls → 1 item specs 224 calls → 2 item specs 204 calls → 4 item specs 196 calls → 1 item specs 164 calls → 13 item specs 160 calls → 2 item specs 151 calls → 3 item specs 144 calls → 53 item specs 140 calls → 6 item specs 138 calls → 4 item specs 134 calls → 1 item specs 132 calls → 7 item specs 122 calls → 2 item specs 117 calls → 14 item specs 113 calls → 124 item specs 111 calls → 1 item specs 110 calls → 2 item specs 109 calls → 1 item specs 101 calls → 3 item specs 100 calls → 2 item specs 99 calls → 1 item specs 98 calls → 1 item specs 91 calls → 5 item specs 89 calls → 59 item specs 86 calls → 2 item specs 84 calls → 1 item specs 82 calls → 2 item specs 80 calls → 7 item specs 78 calls → 1 item specs 76 calls → 2 item specs 75 calls → 1 item specs 74 calls → 5 item specs 73 calls → 3 item specs 72 calls → 2 item specs 70 calls → 1 item specs 66 calls → 5 item specs 65 calls → 5 item specs 60 calls → 10 item specs 58 calls → 8 item specs 57 calls → 1 item specs 56 calls → 1 item specs 54 calls → 6 item specs 52 calls → 3 item specs 51 calls → 8 item specs 50 calls → 1 item specs 49 calls → 2 item specs 48 calls → 3 item specs 47 calls → 1 item specs 46 calls → 1 item specs 45 calls → 13 item specs 44 calls → 20 item specs 41 calls → 2 item specs 40 calls → 8 item specs 39 calls → 1 item specs 37 calls → 4 item specs 36 calls → 51 item specs 35 calls → 5 item specs 34 calls → 1 item specs 33 calls → 1 item specs 32 calls → 2 item specs 30 calls → 4 item specs 29 calls → 11 item specs 28 calls → 20 item specs 27 calls → 11 item specs 26 calls → 16 item specs 24 calls → 30 item specs 23 calls → 3 item specs 22 calls → 153 item specs 21 calls → 1 item specs 20 calls → 26 item specs 19 calls → 1 item specs 18 calls → 109 item specs 16 calls → 30 item specs 15 calls → 35 item specs 14 calls → 383 item specs 13 calls → 166 item specs 12 calls → 1,051 item specs 11 calls → 1 item specs 10 calls → 70 item specs 9 calls → 43 item specs 8 calls → 7,012 item specs 7 calls → 50 item specs 6 calls → 910 item specs 5 calls → 1,420 item specs 4 calls → 449 item specs 3 calls → 32 item specs 2 calls → 340 item specs 1 calls → 804 item specs ``` </details> ## Initial Benchmark Results ### .NET 10.0 | Method | Mean | Error | StdDev | Gen0 | Allocated | |--------------------------------------------- |--------------:|------------:|------------:|-------:|----------:| | IsItemSpecModifier_AllModifiers | 151.425 ns | 0.1309 ns | 0.1161 ns | - | - | | IsDerivableItemSpecModifier_RecursiveDir | 2.522 ns | 0.0028 ns | 0.0025 ns | - | - | | GetItemSpecModifier_FullPath | 267.552 ns | 0.3441 ns | 0.3050 ns | - | - | | GetItemSpecModifier_Directory | 359.023 ns | 0.7603 ns | 0.6740 ns | 0.0224 | 376 B | | GetItemSpecModifier_ModifiedTime | 28,544.061 ns | 237.0185 ns | 221.7073 ns | - | 176 B | | GetItemSpecModifier_DefiningProjectDirectory | 812.229 ns | 3.3636 ns | 2.9817 ns | 0.0315 | 536 B | | TaskItem_AllDerivableModifiers_Once | 434.5 ns | 4.36 ns | 4.08 ns | 0.0734 | 1232 B | | TaskItem_FilenameAndExtension_Repeated | 908.5 ns | 1.13 ns | 1.00 ns | 0.0381 | 640 B | | TaskItem_Filename_ManyItems | 9,651.3 ns | 29.02 ns | 25.72 ns | 0.4730 | 7920 B | | TaskItem_FullPathDerivedModifiers_Repeated | 2,127.6 ns | 7.45 ns | 6.60 ns | 0.4234 | 7120 B | | ProjectItemInstance_AllDerivableModifiers_Once | 513.4 ns | 2.93 ns | 2.74 ns | 0.0772 | 1296 B | | ProjectItemInstance_FilenameExtension_AllItems | 22,697.6 ns | 68.62 ns | 64.19 ns | 0.8545 | 14384 B | | ProjectItemInstance_FilenameExtension_AllItems_Repeated | 181,612.2 ns | 1,125.69 ns | 940.00 ns | 8.5449 | 143840 B | | ProjectItemInstance_AllDefiningProjectModifiers_Once | 1.559 μs | 0.0047 μs | 0.0040 μs | 0.0572 | 976 B | | ProjectItemInstance_DefiningProjectDirectory_Repeated | 9.092 μs | 0.0654 μs | 0.0580 μs | 0.4883 | 8304 B | | ProjectItemInstance_DefiningProjectNameExtension_AllItems_SingleProject | 12.515 μs | 0.0297 μs | 0.0263 μs | 0.5188 | 8864 B | | ProjectItemInstance_DefiningProjectFullPath_AllItems_MultiProject | 35.245 μs | 0.0405 μs | 0.0379 μs | - | 64 B | | ProjectItemInstance_DefiningProjectDirectory_AllItems_MultiProject_Repeated | 878.931 μs | 3.1495 μs | 2.7919 μs | 48.8281 | 824640 B | | TaskItem_AllDefiningProjectModifiers_Once | 1.430 μs | 0.0027 μs | 0.0023 μs | 0.0534 | 912 B | | TaskItem_DefiningProjectNameExtension_AllItems | 11.628 μs | 0.0289 μs | 0.0241 μs | 0.5188 | 8800 B | | TaskItem_DefiningProjectDirectory_Repeated | 9.121 μs | 0.0192 μs | 0.0170 μs | 0.4883 | 8240 B | ### .NET Framework 4.8.1 | Method | Mean | Error | StdDev | Gen0 | Allocated | |--------------------------------------------- |-------------:|-----------:|----------:|-------:|----------:| | IsItemSpecModifier_AllModifiers | 227.45 ns | 0.297 ns | 0.264 ns | - | - | | IsDerivableItemSpecModifier_RecursiveDir | 10.49 ns | 0.019 ns | 0.018 ns | - | - | | GetItemSpecModifier_FullPath | 1,267.45 ns | 0.844 ns | 0.705 ns | - | - | | GetItemSpecModifier_Directory | 2,433.43 ns | 7.400 ns | 6.560 ns | 0.0954 | 517 B | | GetItemSpecModifier_ModifiedTime | 41,881.06 ns | 111.954 ns | 93.487 ns | 0.1221 | 878 B | | GetItemSpecModifier_DefiningProjectDirectory | 5,467.24 ns | 8.295 ns | 6.926 ns | 0.1602 | 857 B | | TaskItem_AllDerivableModifiers_Once | 5.322 μs | 0.0354 μs | 0.0331 μs | 0.3662 | 1923 B | | TaskItem_FilenameAndExtension_Repeated | 10.238 μs | 0.0108 μs | 0.0101 μs | 0.1373 | 761 B | | TaskItem_Filename_ManyItems | 110.078 μs | 0.1367 μs | 0.1212 μs | 2.3193 | 12379 B | | TaskItem_FullPathDerivedModifiers_Repeated | 26.619 μs | 0.1695 μs | 0.1585 μs | 2.1973 | 11578 B | | ProjectItemInstance_AllDerivableModifiers_Once | 5.525 μs | 0.0311 μs | 0.0276 μs | 0.3662 | 1959 B | | ProjectItemInstance_FilenameExtension_AllItems | 216.406 μs | 0.2767 μs | 0.2160 μs | 2.9297 | 16422 B | | ProjectItemInstance_FilenameExtension_AllItems_Repeated | 2,161.623 μs | 10.4073 μs | 9.2258 μs | 31.2500 | 164225 B | | ProjectItemInstance_AllDefiningProjectModifiers_Once | 9.808 μs | 0.0177 μs | 0.0165 μs | 0.2594 | 1418 B | | ProjectItemInstance_DefiningProjectDirectory_Repeated | 64.204 μs | 0.3983 μs | 0.3726 μs | 2.3193 | 12616 B | | ProjectItemInstance_DefiningProjectNameExtension_AllItems_SingleProject | 131.504 μs | 0.3383 μs | 0.3165 μs | 2.1973 | 12456 B | | ProjectItemInstance_DefiningProjectFullPath_AllItems_MultiProject | 173.171 μs | 0.7242 μs | 0.5654 μs | - | 38 B | | ProjectItemInstance_DefiningProjectDirectory_AllItems_MultiProject_Repeated | 6,399.063 μs | 71.6927 μs | 67.0614 μs | 234.3750 | 1242225 B | | TaskItem_AllDefiningProjectModifiers_Once | 8.636 μs | 0.0177 μs | 0.0147 μs | 0.2594 | 1382 B | | TaskItem_DefiningProjectNameExtension_AllItems | 126.982 μs | 0.2250 μs | 0.2104 μs | 2.1973 | 12420 B | | TaskItem_DefiningProjectDirectory_Repeated | 58.025 μs | 0.1388 μs | 0.1299 μs | 2.3804 | 12579 B | ## Final Benchmark Results ### .NET 10.0 | Method | Mean | Error | StdDev | Gen0 | Allocated | |--------------------------------------------- |--------------:|------------:|------------:|-------:|----------:| | IsItemSpecModifier_AllModifiers | 38.4923 ns | 0.5501 ns | 0.5145 ns | - | - | | IsDerivableItemSpecModifier_RecursiveDir | 0.0000 ns | 0.0000 ns | 0.0000 ns | - | - | | GetItemSpecModifier_FullPath | 260.1019 ns | 0.3623 ns | 0.3212 ns | - | - | | GetItemSpecModifier_Directory | 413.2121 ns | 1.9441 ns | 1.8185 ns | 0.0224 | 376 B | | GetItemSpecModifier_ModifiedTime | 30,272.3116 ns | 408.0450 ns | 381.6855 ns | - | 176 B | | GetItemSpecModifier_DefiningProjectDirectory | 72.3691 ns | 0.0289 ns | 0.0270 ns | - | - | | TaskItem_AllDerivableModifiers_Once | 87.41 ns | 0.226 ns | 0.200 ns | - | - | | TaskItem_FilenameAndExtension_Repeated | 173.68 ns | 1.812 ns | 1.695 ns | - | - | | TaskItem_Filename_ManyItems | 1,856.79 ns | 1.128 ns | 0.942 ns | - | - | | TaskItem_FullPathDerivedModifiers_Repeated | 321.57 ns | 0.301 ns | 0.267 ns | - | - | | ProjectItemInstance_AllDerivableModifiers_Once | 143.78 ns | 0.493 ns | 0.462 ns | 0.0038 | 64 B | | ProjectItemInstance_FilenameExtension_AllItems | 5,343.30 ns | 4.955 ns | 4.138 ns | - | 64 B | | ProjectItemInstance_FilenameExtension_AllItems_Repeated | 67,028.30 ns | 252.985 ns | 224.264 ns | - | 640 B | | ProjectItemInstance_AllDefiningProjectModifiers_Once | 459.4 ns | 0.34 ns | 0.31 ns | 0.0038 | 64 B | | ProjectItemInstance_DefiningProjectDirectory_Repeated | 1,020.5 ns | 0.56 ns | 0.47 ns | 0.0038 | 64 B | | ProjectItemInstance_DefiningProjectNameExtension_AllItems_SingleProject | 20,091.0 ns | 17.96 ns | 16.80 ns | - | 64 B | | ProjectItemInstance_DefiningProjectFullPath_AllItems_MultiProject | 9,946.7 ns | 5.28 ns | 4.68 ns | - | 64 B | | ProjectItemInstance_DefiningProjectDirectory_AllItems_MultiProject_Repeated | 103,960.5 ns | 57.74 ns | 48.21 ns | - | 640 B | | TaskItem_AllDefiningProjectModifiers_Once | 400.5 ns | 0.15 ns | 0.12 ns | - | - | | TaskItem_DefiningProjectNameExtension_AllItems | 19,150.3 ns | 11.55 ns | 10.24 ns | - | - | | TaskItem_DefiningProjectDirectory_Repeated | 970.8 ns | 0.62 ns | 0.55 ns | - | - | ### .NET Framework 4.8.1 | Method | Mean | Error | StdDev | Gen0 | Allocated | |--------------------------------------------- |-------------:|-----------:|----------:|-------:|----------:| | IsItemSpecModifier_AllModifiers | 106.532 ns | 0.4289 ns | 0.4012 ns | - | - | | IsDerivableItemSpecModifier_RecursiveDir | 5.067 ns | 0.0031 ns | 0.0024 ns | - | - | | GetItemSpecModifier_FullPath | 1,331.138 ns | 1.4666 ns | 1.3001 ns | - | - | | GetItemSpecModifier_Directory | 2,471.887 ns | 4.2333 ns | 3.7527 ns | 0.0954 | 517 B | | GetItemSpecModifier_ModifiedTime | 44,773.794 ns | 405.2647 ns | 359.2566 ns | 0.1221 | 878 B | | GetItemSpecModifier_DefiningProjectDirectory | 156.840 ns | 0.2242 ns | 0.1987 ns | - | - | | TaskItem_AllDerivableModifiers_Once | 507.2 ns | 1.19 ns | 1.11 ns | - | - | | TaskItem_FilenameAndExtension_Repeated | 664.7 ns | 0.39 ns | 0.35 ns | - | - | | TaskItem_Filename_ManyItems | 6,916.2 ns | 4.03 ns | 3.77 ns | - | - | | TaskItem_FullPathDerivedModifiers_Repeated | 2,261.6 ns | 3.34 ns | 2.96 ns | - | - | | ProjectItemInstance_AllDerivableModifiers_Once | 688.6 ns | 1.01 ns | 0.94 ns | 0.0067 | 36 B | | ProjectItemInstance_FilenameExtension_AllItems | 20,366.3 ns | 11.28 ns | 10.56 ns | - | 36 B | | ProjectItemInstance_FilenameExtension_AllItems_Repeated | 202,570.4 ns | 271.12 ns | 240.34 ns | - | 362 B | | ProjectItemInstance_AllDefiningProjectModifiers_Once | 1,153.5 ns | 13.83 ns | 12.26 ns | 0.0057 | 36 B | | ProjectItemInstance_DefiningProjectDirectory_Repeated | 2,795.7 ns | 17.33 ns | 16.21 ns | 0.0038 | 36 B | | ProjectItemInstance_DefiningProjectNameExtension_AllItems_SingleProject | 46,236.9 ns | 105.16 ns | 93.22 ns | - | 36 B | | ProjectItemInstance_DefiningProjectFullPath_AllItems_MultiProject | 28,362.1 ns | 34.50 ns | 30.58 ns | - | 36 B | | ProjectItemInstance_DefiningProjectDirectory_AllItems_MultiProject_Repeated | 282,316.9 ns | 1,944.00 ns | 1,818.42 ns | - | 364 B | | TaskItem_AllDefiningProjectModifiers_Once | 965.3 ns | 5.43 ns | 4.53 ns | - | - | | TaskItem_DefiningProjectNameExtension_AllItems | 42,707.8 ns | 179.84 ns | 168.23 ns | - | - | | TaskItem_DefiningProjectDirectory_Repeated | 2,539.1 ns | 9.64 ns | 8.05 ns | - | - |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
In multithreaded (-mt) mode, multiple in-proc node engines run in the same process. Each engine's TraceEngine() method (enabled by MSBUILDDEBUGSCHEDULER=1) wrote to the same EngineTrace_{PID}.txt file with FileShare.Read. When two engines traced concurrently, the second got an IOException, which fatally crashed the ActionBlock work queue. All subsequent Post() calls were silently rejected, causing request completions to be dropped and the scheduler to deadlock.
Root Cause
BuildRequestEngine.TraceEngine() -> FileUtilities.OpenWrite(FileShare.Read) -> IOException -> QueueAction catch handler rethrows -> ActionBlock faults permanently -> subsequent state-change posts silently rejected -> request completion lost -> deadlock
The lock(this) in TraceEngine() only synchronizes within the same engine instance. In -mt mode each in-proc node has its own engine, so the lock provides no cross-engine protection.
Fix
Test
Added MultiThreadedBuild_WithDebugSchedulerTracing_DoesNotDeadlock regression test that sets MSBUILDDEBUGSCHEDULER=1 and builds a root project with two child projects in parallel using MultiThreaded=true. Verifies the build completes successfully (previously deadlocked).