diff --git a/documentation/specs/event-source.md b/documentation/specs/event-source.md index ca27f7a9d71..5f684c3bc92 100644 --- a/documentation/specs/event-source.md +++ b/documentation/specs/event-source.md @@ -27,6 +27,16 @@ EventSource is primarily used to profile code. For MSBuild specifically, a major | PacketReadSize | Reports the size of a packet sent between nodes. Note that this does not include time information. | | Parse | Parses an XML document into a ProjectRootElement. | | ProjectGraphConstruction | Constructs a dependency graph among projects. | +| ProjectRootElementCacheGet | Wraps a top-level call to `ProjectRootElementCache.Get`. The Stop event reports an outcome string (`WeakHit`, `WeakHitInvalidated`, `PreserveFormattingReload`, `MissLoaded`, `MissAfterPerFileLockHit`, `Null`) used to compute hit/miss ratios. | +| ProjectRootElementCacheLockWait | Brackets the time spent waiting to acquire the global cache lock (`_locker`). Parameterized by `operation` (`GetOrLoadRead`, `AddEntry`, `RenameEntry`, `Clear`, `DiscardStrongReferences`, `DiscardImplicitReferences`, `DiscardAnyWeakReference`, `ForgetEntryIfExists`). | +| ProjectRootElementCacheLockHeld | Brackets the time spent doing work under the global cache lock. Same `operation` taxonomy as `ProjectRootElementCacheLockWait`. | +| ProjectRootElementCacheBoost | Wraps a single `BoostEntryInStrongCache` call. Stop reports the linear scan depth, current strong cache size, and whether the entry was found (move-to-front) or newly added. | +| ProjectRootElementCacheFileLockWait | Brackets the time spent waiting to acquire the per-file load lock. Stop reports whether this thread created the lock object or adopted one from a concurrent loader. | +| ProjectRootElementCacheLoadDelegateInvoked / Completed | Brackets the actual XML parse via the load delegate. Comparing this count against `ProjectRootElementCacheGet` outcomes shows how often the per-file lock prevented duplicate loads. | +| ProjectRootElementCachePreserveFormattingReload | Brackets the in-place `Reload` triggered by a `preserveFormatting` mismatch. This call currently runs while the global cache lock is held. | +| ProjectRootElementCacheAddedHandler | Brackets the invocation of the `ProjectRootElementAdded` event handler. This call currently runs while the global cache lock is held; the duration measures external/user code under the lock. | +| ProjectRootElementCacheIsInvalidEntry | Brackets `IsInvalidEntry`. Stop reports whether a file `stat` was actually performed and whether the cached entry was deemed invalid. | +| ProjectRootElementCacheDiscardImplicitReferences | Reports the size and outcome of a `DiscardImplicitReferences` rebuild (weak count iterated, strong count before, retained weak/strong counts). | | RarComputeClosure | Resolves references from, for example, properties to explicit values. Used in resolving assembly references (RAR). | | RarLogResults | Logs the results from having resolved assembly references (RAR). | | RarOverall | Initiates the process of resolving assembly references (RAR). | diff --git a/src/Build/Evaluation/ProjectRootElementCache.cs b/src/Build/Evaluation/ProjectRootElementCache.cs index d0cb124e2e6..04030d0db72 100644 --- a/src/Build/Evaluation/ProjectRootElementCache.cs +++ b/src/Build/Evaluation/ProjectRootElementCache.cs @@ -10,6 +10,7 @@ using System.Xml; using Microsoft.Build.Collections; using Microsoft.Build.Construction; +using Microsoft.Build.Eventing; using Microsoft.Build.Framework; using Microsoft.Build.Internal; using ErrorUtilities = Microsoft.Build.Shared.ErrorUtilities; @@ -146,6 +147,31 @@ public void Dispose() /// private object _locker = new object(); + /// + /// Communicates which branch of served a request, + /// for the event. + /// + private enum GetOrLoadOutcome + { + /// Weak miss; loader was null, returned null. + NoEntryNoLoader, + + /// Weak miss; loader was provided and invoked, new PRE returned. + NoEntryLoaded, + + /// Weak hit but stale; loader was null, returned null. + InvalidNoLoader, + + /// Weak hit but stale; loader was provided and invoked, new PRE returned. + InvalidReloaded, + + /// Weak hit, valid; cached PRE returned. + Valid, + + /// Weak hit, valid; PRE reloaded in place because preserveFormatting differed. + PreserveFormattingReload, + } + /// /// Creates an empty cache. /// @@ -166,61 +192,74 @@ internal ProjectRootElementCache(bool autoReloadFromDisk, bool loadProjectsReadO /// private bool IsInvalidEntry(string projectFile, ProjectRootElement projectRootElement) { - // When we do not _autoReloadFromDisk we expect that cached value is always valid. - // Usually lifespan of cache is expected to be build duration (process will terminate after build). - if (projectRootElement == null || !_autoReloadFromDisk) - { - return false; - } - - // If the project file is non modifiable, assume it is up to date and consider the cached value valid. - if (!Traits.Instance.EscapeHatches.AlwaysDoImmutableFilesUpToDateCheck && FileClassifier.Shared.IsNonModifiable(projectFile)) + MSBuildEventSource.Log.ProjectRootElementCacheIsInvalidEntryStart(projectFile); + bool didStat = false; + bool wasInvalid = false; + try { - return false; - } - - FileInfo fileInfo = FileUtilities.GetFileInfoNoThrow(projectFile); + // When we do not _autoReloadFromDisk we expect that cached value is always valid. + // Usually lifespan of cache is expected to be build duration (process will terminate after build). + if (projectRootElement == null || !_autoReloadFromDisk) + { + return false; + } - // If the file doesn't exist on disk, go ahead and use the cached version. - // It's an in-memory project that hasn't been saved yet. - if (fileInfo == null) - { - return false; - } + // If the project file is non modifiable, assume it is up to date and consider the cached value valid. + if (!Traits.Instance.EscapeHatches.AlwaysDoImmutableFilesUpToDateCheck && FileClassifier.Shared.IsNonModifiable(projectFile)) + { + return false; + } - if (fileInfo.LastWriteTime != projectRootElement.LastWriteTimeWhenRead) - { - // File was changed on disk by external means. Cached version is no longer valid. - // We could throw here or ignore the problem, but it is a common and reasonable pattern to change a file - // externally and load a new project over it to see the new content. So we dump it from the cache - // to force a load from disk. There might then exist more than one ProjectRootElement with the same path, - // but clients ought not get themselves into such a state - and unless they save them to disk, - // it may not be a problem. - return true; - } - else if (s_сheckFileContent) - { - // QA tests run too fast for the timestamp check to work. This environment variable is for their - // use: it checks the file content as well as the timestamp. That's better than completely disabling - // the cache as we get test coverage of the rest of the cache code. - XmlDocument document = new XmlDocument(); - document.PreserveWhitespace = projectRootElement.XmlDocument.PreserveWhitespace; + didStat = true; + FileInfo fileInfo = FileUtilities.GetFileInfoNoThrow(projectFile); - using (var xtr = XmlReaderExtension.Create(projectRootElement.FullPath, projectRootElement.ProjectRootElementCache.LoadProjectsReadOnly)) + // If the file doesn't exist on disk, go ahead and use the cached version. + // It's an in-memory project that hasn't been saved yet. + if (fileInfo == null) { - document.Load(xtr.Reader); + return false; } - string diskContent = document.OuterXml; - string cacheContent = projectRootElement.XmlDocument.OuterXml; - - if (diskContent != cacheContent) + if (fileInfo.LastWriteTime != projectRootElement.LastWriteTimeWhenRead) { + // File was changed on disk by external means. Cached version is no longer valid. + // We could throw here or ignore the problem, but it is a common and reasonable pattern to change a file + // externally and load a new project over it to see the new content. So we dump it from the cache + // to force a load from disk. There might then exist more than one ProjectRootElement with the same path, + // but clients ought not get themselves into such a state - and unless they save them to disk, + // it may not be a problem. + wasInvalid = true; return true; } - } + else if (s_сheckFileContent) + { + // QA tests run too fast for the timestamp check to work. This environment variable is for their + // use: it checks the file content as well as the timestamp. That's better than completely disabling + // the cache as we get test coverage of the rest of the cache code. + XmlDocument document = new XmlDocument(); + document.PreserveWhitespace = projectRootElement.XmlDocument.PreserveWhitespace; + + using (var xtr = XmlReaderExtension.Create(projectRootElement.FullPath, projectRootElement.ProjectRootElementCache.LoadProjectsReadOnly)) + { + document.Load(xtr.Reader); + } - return false; + string diskContent = document.OuterXml; + string cacheContent = projectRootElement.XmlDocument.OuterXml; + + if (diskContent != cacheContent) + { + wasInvalid = true; + return true; + } + } + + return false; + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheIsInvalidEntryStop(projectFile, didStat, wasInvalid); + } } /// @@ -259,65 +298,128 @@ internal override ProjectRootElement Get(string projectFile, OpenProjectRootElem // Should already have been canonicalized ErrorUtilities.VerifyThrowInternalRooted(projectFile); - // First try getting the ProjectRootElement from the cache. - ProjectRootElement projectRootElement = GetOrLoad(projectFile, loadProjectRootElement: null, isExplicitlyLoaded, preserveFormatting); - - if (projectRootElement != null || loadProjectRootElement == null) - { - // If we found it or no load callback was specified, we are done. - return projectRootElement; - } - + MSBuildEventSource.Log.ProjectRootElementCacheGetStart(projectFile, loadProjectRootElement != null); + string outcome = "Null"; try { - // We are about to load. Take a per-file lock to prevent multiple threads from duplicating the work multiple times. - object perFileLock = _fileLoadLocks.GetOrAdd(projectFile, static _ => new object()); - lock (perFileLock) + // First try getting the ProjectRootElement from the cache. + ProjectRootElement projectRootElement = GetOrLoad(projectFile, loadProjectRootElement: null, isExplicitlyLoaded, preserveFormatting, out GetOrLoadOutcome firstOutcome); + + if (projectRootElement != null || loadProjectRootElement == null) { - // Call GetOrLoad again, this time with the OpenProjectRootElement callback. - return GetOrLoad(projectFile, loadProjectRootElement, isExplicitlyLoaded, preserveFormatting); + // If we found it or no load callback was specified, we are done. + outcome = OutcomeToString(firstOutcome, fromPerFileLockedCall: false); + return projectRootElement; + } + + try + { + // We are about to load. Take a per-file lock to prevent multiple threads from duplicating the work multiple times. + // Capture a sentinel so we can tell whether we created the lock object ourselves + // (no concurrent loader) or adopted one already in flight (potential single-flight dedup). + object newLock = null; + object perFileLock = _fileLoadLocks.GetOrAdd(projectFile, _ => newLock = new object()); + bool wasFreshlyCreatedLockObject = ReferenceEquals(perFileLock, newLock); + + MSBuildEventSource.Log.ProjectRootElementCacheFileLockWaitStart(projectFile); + lock (perFileLock) + { + MSBuildEventSource.Log.ProjectRootElementCacheFileLockWaitStop(projectFile, wasFreshlyCreatedLockObject); + + // Call GetOrLoad again, this time with the OpenProjectRootElement callback. + ProjectRootElement loaded = GetOrLoad(projectFile, loadProjectRootElement, isExplicitlyLoaded, preserveFormatting, out GetOrLoadOutcome secondOutcome); + outcome = OutcomeToString(secondOutcome, fromPerFileLockedCall: true); + return loaded; + } + } + finally + { + // Remove the lock object as we have otherwise no good way of preventing _fileLoadLocks from growing unboundedly. + // If another thread is inside the lock, we effectively create a race condition where someone else may enter + // GetOrLoad. This is OK because this fine-grained locking is just a perf optimization, and we have either loaded + // the ProjectRootElement by now, or it is an error condition where perf is not critical. + _fileLoadLocks.TryRemove(projectFile, out _); } } finally { - // Remove the lock object as we have otherwise no good way of preventing _fileLoadLocks from growing unboundedly. - // If another thread is inside the lock, we effectively create a race condition where someone else may enter - // GetOrLoad. This is OK because this fine-grained locking is just a perf optimization, and we have either loaded - // the ProjectRootElement by now, or it is an error condition where perf is not critical. - _fileLoadLocks.TryRemove(projectFile, out _); + MSBuildEventSource.Log.ProjectRootElementCacheGetStop(projectFile, outcome); } } + /// + /// Translates a into the public outcome string emitted on the Get Stop event. + /// + /// The branch GetOrLoad took. + /// + /// True if this is the second GetOrLoad call (after acquiring the per-file load lock). + /// In that case, a Valid outcome means another thread loaded the entry while we waited + /// (single-flight dedup), so we report "MissAfterPerFileLockHit" instead of "WeakHit". + /// + private static string OutcomeToString(GetOrLoadOutcome outcome, bool fromPerFileLockedCall) + { + return outcome switch + { + GetOrLoadOutcome.Valid => fromPerFileLockedCall ? "MissAfterPerFileLockHit" : "WeakHit", + GetOrLoadOutcome.PreserveFormattingReload => "PreserveFormattingReload", + GetOrLoadOutcome.InvalidReloaded => "WeakHitInvalidated", + GetOrLoadOutcome.NoEntryLoaded => "MissLoaded", + GetOrLoadOutcome.NoEntryNoLoader => "Null", + GetOrLoadOutcome.InvalidNoLoader => "Null", + _ => "Null", + }; + } + /// /// A helper used by . /// private ProjectRootElement GetOrLoad(string projectFile, OpenProjectRootElement loadProjectRootElement, bool isExplicitlyLoaded, - bool? preserveFormatting) + bool? preserveFormatting, out GetOrLoadOutcome outcome) { ProjectRootElement projectRootElement; + bool didPreserveFormattingReload = false; + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(projectFile, "GetOrLoadRead"); lock (_locker) { - _weakCache.TryGetValue(projectFile, out projectRootElement); - - if (projectRootElement != null) + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(projectFile, "GetOrLoadRead"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(projectFile, "GetOrLoadRead"); + try { - BoostEntryInStrongCache(projectRootElement); + _weakCache.TryGetValue(projectFile, out projectRootElement); - // An implicit load will never reset the explicit flag. - if (isExplicitlyLoaded) + if (projectRootElement != null) { - projectRootElement.MarkAsExplicitlyLoaded(); + BoostEntryInStrongCache(projectRootElement); + + // An implicit load will never reset the explicit flag. + if (isExplicitlyLoaded) + { + projectRootElement.MarkAsExplicitlyLoaded(); + } + } + else + { + DebugTraceCache("Not found in cache: ", projectFile); } - } - else - { - DebugTraceCache("Not found in cache: ", projectFile); - } - if (preserveFormatting != null && projectRootElement != null && projectRootElement.XmlDocument.PreserveWhitespace != preserveFormatting) + if (preserveFormatting != null && projectRootElement != null && projectRootElement.XmlDocument.PreserveWhitespace != preserveFormatting) + { + // Cached project doesn't match preserveFormatting setting, so reload it + MSBuildEventSource.Log.ProjectRootElementCachePreserveFormattingReloadStart(projectFile); + try + { + projectRootElement.Reload(true, preserveFormatting); + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCachePreserveFormattingReloadStop(projectFile); + } + didPreserveFormattingReload = true; + } + } + finally { - // Cached project doesn't match preserveFormatting setting, so reload it - projectRootElement.Reload(true, preserveFormatting); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(projectFile, "GetOrLoadRead"); } } @@ -330,21 +432,37 @@ private ProjectRootElement GetOrLoad(string projectFile, OpenProjectRootElement if (loadProjectRootElement == null) { - if (projectRootElement == null || projectRootElementIsInvalid) + if (projectRootElement == null) { + outcome = GetOrLoadOutcome.NoEntryNoLoader; return null; } - else + if (projectRootElementIsInvalid) { - DebugTraceCache("Satisfied from XML cache: ", projectFile); - return projectRootElement; + outcome = GetOrLoadOutcome.InvalidNoLoader; + return null; } + + DebugTraceCache("Satisfied from XML cache: ", projectFile); + outcome = didPreserveFormattingReload ? GetOrLoadOutcome.PreserveFormattingReload : GetOrLoadOutcome.Valid; + return projectRootElement; } // Use openProjectRootElement to reload the element if the cache element does not exist or need to be reloaded. if (projectRootElement == null || projectRootElementIsInvalid) { - projectRootElement = loadProjectRootElement(projectFile, this); + bool wasInvalid = projectRootElementIsInvalid; + MSBuildEventSource.Log.ProjectRootElementCacheLoadDelegateInvoked(projectFile); + bool loaderSucceeded = false; + try + { + projectRootElement = loadProjectRootElement(projectFile, this); + loaderSucceeded = projectRootElement != null; + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLoadDelegateCompleted(projectFile, loaderSucceeded); + } ErrorUtilities.VerifyThrowInternalNull(projectRootElement, "projectRootElement"); ErrorUtilities.VerifyThrow( projectRootElement.FullPath.Equals(projectFile, StringComparison.OrdinalIgnoreCase), @@ -361,10 +479,13 @@ private ProjectRootElement GetOrLoad(string projectFile, OpenProjectRootElement // And here its entry will be replaced with the loaded projectRootElement. This is fine: // if loaded projectRootElement is out of date (so, it changed since the time we loaded it), it will be updated the next time some thread calls Get function. AddEntry(projectRootElement); + + outcome = wasInvalid ? GetOrLoadOutcome.InvalidReloaded : GetOrLoadOutcome.NoEntryLoaded; } else { DebugTraceCache("Satisfied from XML cache: ", projectFile); + outcome = didPreserveFormattingReload ? GetOrLoadOutcome.PreserveFormattingReload : GetOrLoadOutcome.Valid; } return projectRootElement; @@ -375,11 +496,30 @@ private ProjectRootElement GetOrLoad(string projectFile, OpenProjectRootElement /// internal override void AddEntry(ProjectRootElement projectRootElement) { + string projectFile = projectRootElement.FullPath ?? string.Empty; + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(projectFile, "AddEntry"); lock (_locker) { - RenameEntryInternal(null, projectRootElement); + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(projectFile, "AddEntry"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(projectFile, "AddEntry"); + try + { + RenameEntryInternal(null, projectRootElement); - RaiseProjectRootElementAddedToCacheEvent(projectRootElement); + MSBuildEventSource.Log.ProjectRootElementCacheAddedHandlerStart(projectFile); + try + { + RaiseProjectRootElementAddedToCacheEvent(projectRootElement); + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheAddedHandlerStop(projectFile); + } + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(projectFile, "AddEntry"); + } } } @@ -389,10 +529,21 @@ internal override void AddEntry(ProjectRootElement projectRootElement) /// internal override void RenameEntry(string oldFullPath, ProjectRootElement projectRootElement) { + string projectFile = projectRootElement.FullPath ?? oldFullPath ?? string.Empty; + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(projectFile, "RenameEntry"); lock (_locker) { - ErrorUtilities.VerifyThrowArgumentLength(oldFullPath); - RenameEntryInternal(oldFullPath, projectRootElement); + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(projectFile, "RenameEntry"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(projectFile, "RenameEntry"); + try + { + ErrorUtilities.VerifyThrowArgumentLength(oldFullPath); + RenameEntryInternal(oldFullPath, projectRootElement); + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(projectFile, "RenameEntry"); + } } } @@ -430,14 +581,24 @@ internal override ProjectRootElement TryGet(string projectFile, bool? preserveFo /// internal override void DiscardStrongReferences() { + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(string.Empty, "DiscardStrongReferences"); lock (_locker) { - DebugTraceCache("Clearing strong refs: ", _strongCache.Count); + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(string.Empty, "DiscardStrongReferences"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(string.Empty, "DiscardStrongReferences"); + try + { + DebugTraceCache("Clearing strong refs: ", _strongCache.Count); - _strongCache = new LinkedList(); + _strongCache = new LinkedList(); - // A scavenge of the weak cache is probably not worth it as - // the GC would have had to run immediately after the line above. + // A scavenge of the weak cache is probably not worth it as + // the GC would have had to run immediately after the line above. + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(string.Empty, "DiscardStrongReferences"); + } } } @@ -447,10 +608,20 @@ internal override void DiscardStrongReferences() /// internal override void Clear() { + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(string.Empty, "Clear"); lock (_locker) { - _weakCache = new WeakValueDictionary(StringComparer.OrdinalIgnoreCase); - _strongCache = new LinkedList(); + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(string.Empty, "Clear"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(string.Empty, "Clear"); + try + { + _weakCache = new WeakValueDictionary(StringComparer.OrdinalIgnoreCase); + _strongCache = new LinkedList(); + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(string.Empty, "Clear"); + } } } @@ -465,37 +636,59 @@ internal override void DiscardImplicitReferences() return; } + int weakCount = 0; + int strongCount = 0; + int retainedWeakCount = 0; + int retainedStrongCount = 0; + + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(string.Empty, "DiscardImplicitReferences"); lock (_locker) { - // Make a new Weak cache only with items that have been explicitly loaded, this will be a small number, there will most likely - // be many items which were not explicitly loaded (ie p2p references). - WeakValueDictionary oldWeakCache = _weakCache; - _weakCache = new WeakValueDictionary(StringComparer.OrdinalIgnoreCase); + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(string.Empty, "DiscardImplicitReferences"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(string.Empty, "DiscardImplicitReferences"); + try + { + // Make a new Weak cache only with items that have been explicitly loaded, this will be a small number, there will most likely + // be many items which were not explicitly loaded (ie p2p references). + WeakValueDictionary oldWeakCache = _weakCache; + _weakCache = new WeakValueDictionary(StringComparer.OrdinalIgnoreCase); - LinkedList oldStrongCache = _strongCache; - _strongCache = new LinkedList(); + LinkedList oldStrongCache = _strongCache; + strongCount = oldStrongCache.Count; + _strongCache = new LinkedList(); - foreach (KeyValuePair kvp in oldWeakCache) - { - if (kvp.Value is null) + foreach (KeyValuePair kvp in oldWeakCache) { - continue; - } + if (kvp.Value is null) + { + continue; + } - if (kvp.Value.IsExplicitlyLoaded) - { - _weakCache[kvp.Key] = kvp.Value; - } + weakCount++; - if (oldStrongCache.Contains(kvp.Value)) - { if (kvp.Value.IsExplicitlyLoaded) { - _strongCache.AddFirst(kvp.Value); + _weakCache[kvp.Key] = kvp.Value; + retainedWeakCount++; + } + + if (oldStrongCache.Contains(kvp.Value)) + { + if (kvp.Value.IsExplicitlyLoaded) + { + _strongCache.AddFirst(kvp.Value); + retainedStrongCount++; + } } } } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(string.Empty, "DiscardImplicitReferences"); + } } + + MSBuildEventSource.Log.ProjectRootElementCacheDiscardImplicitReferences(weakCount, strongCount, retainedWeakCount, retainedStrongCount); } /// @@ -516,9 +709,20 @@ internal override void DiscardAnyWeakReference(ProjectRootElement projectRootEle // A PRE may be unnamed if it was only used in memory. if (projectRootElement.FullPath != null) { + string projectFile = projectRootElement.FullPath; + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(projectFile, "DiscardAnyWeakReference"); lock (_locker) { - _weakCache.Remove(projectRootElement.FullPath); + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(projectFile, "DiscardAnyWeakReference"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(projectFile, "DiscardAnyWeakReference"); + try + { + _weakCache.Remove(projectRootElement.FullPath); + } + finally + { + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(projectFile, "DiscardAnyWeakReference"); + } } } } @@ -578,30 +782,43 @@ private void RenameEntryInternal(string oldFullPathIfAny, ProjectRootElement pro /// private void BoostEntryInStrongCache(ProjectRootElement projectRootElement) { - LinkedListNode node = _strongCache.First; - - while (node != null) + string projectFile = projectRootElement.FullPath ?? string.Empty; + MSBuildEventSource.Log.ProjectRootElementCacheBoostStart(projectFile); + int scanDepth = 0; + bool wasFound = false; + try { - if (Object.ReferenceEquals(node.Value, projectRootElement)) + LinkedListNode node = _strongCache.First; + + while (node != null) { - // DebugTraceCache("Boosting: ", projectRootElement.FullPath); - _strongCache.Remove(node); - _strongCache.AddFirst(node); + scanDepth++; + if (Object.ReferenceEquals(node.Value, projectRootElement)) + { + // DebugTraceCache("Boosting: ", projectRootElement.FullPath); + _strongCache.Remove(node); + _strongCache.AddFirst(node); - return; + wasFound = true; + return; + } + + node = node.Next; } - node = node.Next; - } + _strongCache.AddFirst(projectRootElement); - _strongCache.AddFirst(projectRootElement); + if (_strongCache.Count > s_maximumStrongCacheSize) + { + node = _strongCache.Last; - if (_strongCache.Count > s_maximumStrongCacheSize) + DebugTraceCache("Shedding: ", node.Value.FullPath); + _strongCache.Remove(node); + } + } + finally { - node = _strongCache.Last; - - DebugTraceCache("Shedding: ", node.Value.FullPath); - _strongCache.Remove(node); + MSBuildEventSource.Log.ProjectRootElementCacheBoostStop(projectFile, scanDepth, _strongCache.Count, wasFound); } } @@ -631,11 +848,22 @@ private void ForgetEntry(ProjectRootElement projectRootElement) /// private void ForgetEntryIfExists(ProjectRootElement projectRootElement) { + string projectFile = projectRootElement.FullPath ?? string.Empty; + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStart(projectFile, "ForgetEntryIfExists"); lock (_locker) { - if (_weakCache.TryGetValue(projectRootElement.FullPath, out var cached) && cached == projectRootElement) + MSBuildEventSource.Log.ProjectRootElementCacheLockWaitStop(projectFile, "ForgetEntryIfExists"); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStart(projectFile, "ForgetEntryIfExists"); + try + { + if (_weakCache.TryGetValue(projectRootElement.FullPath, out var cached) && cached == projectRootElement) + { + ForgetEntry(projectRootElement); + } + } + finally { - ForgetEntry(projectRootElement); + MSBuildEventSource.Log.ProjectRootElementCacheLockHeldStop(projectFile, "ForgetEntryIfExists"); } } } diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index ddd88e832a1..d953deec7a2 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -821,6 +821,220 @@ public void TaskExecuteInHostStop(string taskName, bool succeeded) { WriteEvent(112, taskName, succeeded); } + + // ----------------------------------------------------------------- + // ProjectRootElementCache instrumentation (events 113-131). + // + // These are profiling events used to characterize lock contention and + // hot-path costs in ProjectRootElementCache. They add no behavior; + // they exist only to be observed via PerfView/EventListener captures. + // + // Naming convention: every method begins with "ProjectRootElementCache" + // so PerfView can group them. Start/Stop pairs auto-correlate per + // thread via EventSource activity tracking. + // ----------------------------------------------------------------- + + /// + /// Wraps a top-level call to ProjectRootElementCache.Get. + /// + /// Full path of the project being requested. + /// True if the caller passed a load delegate (i.e. could trigger an XML parse). + [Event(113, Keywords = Keywords.All)] + public void ProjectRootElementCacheGetStart(string projectFile, bool hasLoader) + { + WriteEvent(113, projectFile, hasLoader); + } + + /// Full path of the project being requested. + /// + /// One of: WeakHit, WeakHitInvalidated, PreserveFormattingReload, MissLoaded, + /// MissAfterPerFileLockHit, Null. Drives hit/miss aggregation. + /// + [Event(114, Keywords = Keywords.All)] + public void ProjectRootElementCacheGetStop(string projectFile, string outcome) + { + WriteEvent(114, projectFile, outcome); + } + + /// + /// Fires immediately before acquiring the global cache lock. + /// The interval to is + /// queueing/contention time on _locker. + /// + /// Path being operated on, or empty if not associated with one file. + /// + /// Symbolic operation name: GetOrLoadRead, AddEntry, RenameEntry, Clear, + /// DiscardStrongReferences, DiscardImplicitReferences, DiscardAnyWeakReference, + /// ForgetEntryIfExists. + /// + [Event(115, Keywords = Keywords.All)] + public void ProjectRootElementCacheLockWaitStart(string projectFile, string operation) + { + WriteEvent(115, projectFile, operation); + } + + /// Path being operated on, or empty if not associated with one file. + /// Operation name; see . + [Event(116, Keywords = Keywords.All)] + public void ProjectRootElementCacheLockWaitStop(string projectFile, string operation) + { + WriteEvent(116, projectFile, operation); + } + + /// + /// Fires immediately after acquiring the global cache lock. + /// The interval to is + /// time spent doing work under _locker. + /// + /// Path being operated on, or empty if not associated with one file. + /// Operation name; see . + [Event(117, Keywords = Keywords.All)] + public void ProjectRootElementCacheLockHeldStart(string projectFile, string operation) + { + WriteEvent(117, projectFile, operation); + } + + /// Path being operated on, or empty if not associated with one file. + /// Operation name; see . + [Event(118, Keywords = Keywords.All)] + public void ProjectRootElementCacheLockHeldStop(string projectFile, string operation) + { + WriteEvent(118, projectFile, operation); + } + + /// + /// Wraps a single call to BoostEntryInStrongCache. The Stop event + /// reports the linear scan depth so the O(n) walk can be characterized. + /// + /// Path of the entry being boosted. + [Event(119, Keywords = Keywords.All)] + public void ProjectRootElementCacheBoostStart(string projectFile) + { + WriteEvent(119, projectFile); + } + + /// Path of the entry that was boosted. + /// Number of Object.ReferenceEquals comparisons performed walking the strong cache. + /// Strong cache size after the operation. + /// True if the entry was already in the strong cache (move-to-front); false if it was newly added. + [Event(120, Keywords = Keywords.All)] + public void ProjectRootElementCacheBoostStop(string projectFile, int scanDepth, int strongCacheSize, bool wasFound) + { + WriteEvent(120, projectFile, scanDepth, strongCacheSize, wasFound); + } + + /// + /// Fires before acquiring the per-file load lock. The interval to + /// measures + /// time waiting for another thread to finish loading the same path. + /// + /// Path whose load is being serialized. + [Event(121, Keywords = Keywords.All)] + public void ProjectRootElementCacheFileLockWaitStart(string projectFile) + { + WriteEvent(121, projectFile); + } + + /// Path whose load is being serialized. + /// + /// True if the per-file lock object was created by this thread (no concurrent + /// loader was in flight). False if another thread had already inserted a lock + /// object, suggesting potential single-flight deduplication. + /// + [Event(122, Keywords = Keywords.All)] + public void ProjectRootElementCacheFileLockWaitStop(string projectFile, bool wasFreshlyCreatedLockObject) + { + WriteEvent(122, projectFile, wasFreshlyCreatedLockObject); + } + + /// + /// Fires immediately before invoking the load delegate (which performs the actual XML parse). + /// + /// Path being parsed. + [Event(123, Keywords = Keywords.All)] + public void ProjectRootElementCacheLoadDelegateInvoked(string projectFile) + { + WriteEvent(123, projectFile); + } + + /// Path that was parsed. + /// True if the load delegate returned a non-null PRE without throwing. + [Event(124, Keywords = Keywords.All)] + public void ProjectRootElementCacheLoadDelegateCompleted(string projectFile, bool succeeded) + { + WriteEvent(124, projectFile, succeeded); + } + + /// + /// Wraps the in-place reload triggered when a cached PRE has the wrong preserveFormatting setting. + /// This call currently runs while _locker is held; the duration is "long work under lock". + /// + /// Path being reloaded. + [Event(125, Keywords = Keywords.All)] + public void ProjectRootElementCachePreserveFormattingReloadStart(string projectFile) + { + WriteEvent(125, projectFile); + } + + /// Path being reloaded. + [Event(126, Keywords = Keywords.All)] + public void ProjectRootElementCachePreserveFormattingReloadStop(string projectFile) + { + WriteEvent(126, projectFile); + } + + /// + /// Wraps the invocation of the ProjectRootElementAdded event handler. + /// This call currently runs while _locker is held; the duration is "external work under lock". + /// + /// Path of the PRE being added. + [Event(127, Keywords = Keywords.All)] + public void ProjectRootElementCacheAddedHandlerStart(string projectFile) + { + WriteEvent(127, projectFile); + } + + /// Path of the PRE that was added. + [Event(128, Keywords = Keywords.All)] + public void ProjectRootElementCacheAddedHandlerStop(string projectFile) + { + WriteEvent(128, projectFile); + } + + /// + /// Wraps an invocation of IsInvalidEntry. The Stop event reports + /// whether a file stat actually happened (vs. a short-circuit) and whether + /// the cached entry was deemed invalid. + /// + /// Path being checked. + [Event(129, Keywords = Keywords.All)] + public void ProjectRootElementCacheIsInvalidEntryStart(string projectFile) + { + WriteEvent(129, projectFile); + } + + /// Path that was checked. + /// True if a FileInfo stat was performed (i.e. autoreload mode and not short-circuited). + /// True if the cached entry was deemed stale and should be reloaded. + [Event(130, Keywords = Keywords.All)] + public void ProjectRootElementCacheIsInvalidEntryStop(string projectFile, bool didStat, bool wasInvalid) + { + WriteEvent(130, projectFile, didStat, wasInvalid); + } + + /// + /// Reports the size and outcome of a DiscardImplicitReferences rebuild. + /// + /// Number of entries iterated in the old weak cache. + /// Size of the old strong cache before the rebuild. + /// Number of explicitly-loaded weak entries kept after the rebuild. + /// Number of strong-cache entries kept after the rebuild. + [Event(131, Keywords = Keywords.All)] + public void ProjectRootElementCacheDiscardImplicitReferences(int weakCount, int strongCount, int retainedWeakCount, int retainedStrongCount) + { + WriteEvent(131, weakCount, strongCount, retainedWeakCount, retainedStrongCount); + } + #endregion } }