Reduce duplicated FileUtilities.GetFileTimeStamp calls #78321

ToddGrun · 2025-04-25T18:08:58Z

Inspection of CPU samples during solution load in the c# editing speedometer tests shows over 3 seconds of CPU time spent in File.GetLastWriteTime. Manual debugging showed of opening Roslyn.sln showed 64,195 calls to File.GetLastWriteTime, but only 1,511 unique paths requested. The vast majoriy of the calls originate from SerializerService.CreateChecksum's call to VisualStudioPortableExecutableReference.GetMetadataImpl's access to the lazy _timestamp.

This PR introduces a class to cache the last write time of files, invalidating itself via IFileChangeWatcher notifications (or solution close). The speedometer numbers from the test insertion came back with good results, with the 3 CPU seconds reduced to just about 150 milliseconds.

Test insertion (commit 7): https://dev.azure.com/devdiv/DevDiv/_git/VS/pullrequest/633179

*** Before ***

*** After ***

In draft mode until: 1) Receive input from Jason on whether this approach is reasonable 2) Get results from speedometer run on test insertion indicating this indeed helps If those both happen, will update with more information

...lStudio/Core/Def/ProjectSystem/MetadataReferences/VisualStudioPortableExecutableReference.cs

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

jasonmalinowski

I worry a bit there's a potential here for things to get out of sync if we were to miss a file change notification after having a cached result, or that were to get delayed a bit. If that were to happen, what behavior would we expect? I'm also not sure if leaking the contexts would be a problem -- if we close the solution do we still have file locks on the directories?

I'm also quite surprised generally we're seeing that much expense just reading the time stamps a bunch of times. Is the runtime being inefficient here?

...lStudio/Core/Def/ProjectSystem/MetadataReferences/VisualStudioPortableExecutableReference.cs

ToddGrun · 2025-04-29T19:58:53Z

I worry a bit there's a potential here for things to get out of sync if we were to miss a file change notification after having a cached result, or that were to get delayed a bit. If that were to happen, what behavior would we expect?

This I'm not 100% sure about. I was leaning on this comment for my assumption that getting a slightly outdated timestamp would recover once the workspace responded to the event. I can definitely try and dig a bit more if this worries you.

I'm also not sure if leaking the contexts would be a problem -- if we close the solution do we still have file locks on the directories?

There weren't any locks taken on directories, we were just advising to directory change events. That said, it's better to go ahead unadvise the contexts on solution close, so I went ahead and added that.

I'm also quite surprised generally we're seeing that much expense just reading the time stamps a bunch of times. Is the runtime being inefficient here?

I don't know if inefficient is how I would describe it. As mentioned, there were > 64000 File.GetLastWriteTimeUtc calls being made, so I wouldn't say we were really making their job easy.

2) Cleanup a using

ToddGrun · 2025-04-29T20:40:14Z

I was leaning on this comment for my assumption that getting a slightly outdated timestamp would recover once the workspace responded to the event.

I set a breakpoint in GetTimeStamp after the cache miss and manually modified the last write time of a referenced assembly. Without doing anything in the editor, the breakpoint was hit, making me feel fairly good about the invalidation mechanism here.

FYI, I'm going to run a test insertion again to get numbers as there have been a couple changes I'd like to see measured

Test insertion: https://dev.azure.com/devdiv/DevDiv/_git/VS/pullrequest/633179

Numbers came back good again. Updated the PR description with the new results.

ToddGrun · 2025-05-08T01:13:47Z

@jasonmalinowski -- This is one of the more impactful perf changes I have outstanding, would love to get your thoughts on this.

jasonmalinowski · 2025-05-14T23:44:14Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+            private readonly Dictionary<string, DateTime> _cachedTimestamps = [];
+            private readonly Dictionary<string, IFileChangeContext> _fileChangeContexts = [];
+
+            private FileTimeStampProvider(Workspace workspace)


At first I was concerned that unless this was the real VisualStudioWorkspace that we might be listening to a different workspace's events. I see that's the one yuo're actually importing, but maybe it's best to keep that strongly typed here too to ensure we don't refactor it and grab something else?

jasonmalinowski · 2025-05-14T23:47:20Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+
+            private static FileTimeStampProvider GetInstance(Workspace workspace)
+            {
+                return s_instance ??= new FileTimeStampProvider(workspace);


This is technically a race in that two could create this at once. It's probably fine, but would mean we end up with two subscriptions to the workspace which is kinda strange.

jasonmalinowski · 2025-05-14T23:48:37Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+            {
+                DateTime timestamp;
+
+                lock (_cachedTimestamps)


I could imagine this might be high-traffic enough to be worth doing a ReaderWriterLockSlim here. Did we see any contenetion on this path during load though?

jasonmalinowski · 2025-05-14T23:53:04Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+                    _ = _fileChangeContexts.GetOrAdd(directory, static (directory, arg) =>
+                    {
+                        var (watcher, self) = arg;
+                        var context = watcher.CreateContext([new WatchedDirectory(directory, extensionFilters: [])]);


As a useful optimization, it might be good to watch *.dll and then explicitly watch the file we're caching for. That way we're not getting file notification traffic for things we are unlikely to be watching.

jasonmalinowski · 2025-05-14T23:53:34Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+                    _ = _fileChangeContexts.GetOrAdd(directory, static (directory, arg) =>
+                    {
+                        var (watcher, self) = arg;
+                        var context = watcher.CreateContext([new WatchedDirectory(directory, extensionFilters: [])]);


This directory watch here is going to be recursive, so if we have DLLs at different directories we might already have overlap there.

jasonmalinowski · 2025-05-14T23:56:53Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+
+                lock (_cachedTimestamps)
+                {
+                    // Ensure we are listening for changes to this directory.


We already have watchers being created for each DLL we're consuming in the FileWatchedReferenceFactory; can we move this cache so those can just clear this too?

Since that's already reference counted too, you could remove things from the cache (and avoid caching them) unless somebody already has a watch on it.

jasonmalinowski · 2025-05-15T00:00:35Z

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs

+                var directory = Path.GetDirectoryName(fullPath);
+                timestamp = FileUtilities.GetFileTimeStamp(fullPath);
+
+                lock (_cachedTimestamps)


There is a race here where if there is a file write between the read of the time stamp and taking the lock that things could get out of order:

Thread A reads the older timestamp. Now mentally pause this thread.

File is touched.

Thread B reads the newer timestamp. Takes lock, updates the map.

Mentally unpause Thread A. Writes the old timestamp.

You'll have to think if this matters or not.

...lStudio/Core/Def/ProjectSystem/MetadataReferences/VisualStudioPortableExecutableReference.cs

jasonmalinowski · 2025-05-15T00:21:29Z

@ToddGrun My concern about missed events is since we closed #56023 without fixing it, if we had a situation where the user is doing a build and lots of writes are happening to DLLs on disk -- do we have a situation where we drop a timestamp update and the timestamp is now cached stale until they unload/reload their solution?

I'm also wondering if rather than caching the timestamps it just makes sense to make sense to just have VisualStudioMetadataReferenceManager._metadataCache be cleared directly when the file changes and just dispense of the file timestamps all together. I think the original model here was so that we absolutely could immediately respond to a DLL being changed on disk. If it's the case that we are now expecting a file watch to be successfully fired before we'll do it, then we can just be a bit more direct with the intent here.

ToddGrun requested a review from jasonmalinowski April 25, 2025 18:09

ghost added Area-IDE untriaged Issues and PRs which have not yet been triaged by a lead labels Apr 25, 2025

Cleanup

45b2748

ToddGrun commented Apr 25, 2025

View reviewed changes

...lStudio/Core/Def/ProjectSystem/MetadataReferences/VisualStudioPortableExecutableReference.cs Show resolved Hide resolved

CyrusNajmabadi reviewed Apr 25, 2025

View reviewed changes

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs Outdated Show resolved Hide resolved

CyrusNajmabadi reviewed Apr 25, 2025

View reviewed changes

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs Show resolved Hide resolved

Move an expensive call out of the lock.

b3fc766

ToddGrun changed the title *** WIP: Significantly reduce FileUtilities.GetFileTimeStamp calls Reduce duplicated FileUtilities.GetFileTimeStamp calls Apr 26, 2025

ToddGrun marked this pull request as ready for review April 26, 2025 23:29

ToddGrun requested a review from a team as a code owner April 26, 2025 23:29

jasonmalinowski reviewed Apr 28, 2025

View reviewed changes

...ctSystem/MetadataReferences/VisualStudioPortableExecutableReference.FileTimeStampProvider.cs Show resolved Hide resolved

jasonmalinowski reviewed Apr 28, 2025

View reviewed changes

...lStudio/Core/Def/ProjectSystem/MetadataReferences/VisualStudioPortableExecutableReference.cs Show resolved Hide resolved

...lStudio/Core/Def/ProjectSystem/MetadataReferences/VisualStudioPortableExecutableReference.cs Show resolved Hide resolved

ToddGrun added 2 commits April 29, 2025 10:07

Merge branch 'main' into dev/toddgrun/FileTimeStampProvider

f8b73da

Handle cache invalidation

bcb0f1c

1) Fix condition that got inverted

d9e2011

2) Cleanup a using

ToddGrun added 4 commits April 30, 2025 13:49

Merge branch 'main' into dev/toddgrun/FileTimeStampProvider

731291b

Merge branch 'main' into dev/toddgrun/FileTimeStampProvider

04b41c5

Merge branch 'main' into dev/toddgrun/FileTimeStampProvider

4ad0a18

Merge branch 'main' into dev/toddgrun/FileTimeStampProvider

d277b33

jasonmalinowski reviewed May 14, 2025

View reviewed changes

jasonmalinowski reviewed May 15, 2025

View reviewed changes

jasonmalinowski self-assigned this May 16, 2025

Reduce duplicated FileUtilities.GetFileTimeStamp calls #78321

Are you sure you want to change the base?

Reduce duplicated FileUtilities.GetFileTimeStamp calls #78321

Uh oh!

Conversation

ToddGrun commented Apr 25, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jasonmalinowski left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

ToddGrun commented Apr 29, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ToddGrun commented Apr 29, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ToddGrun commented May 8, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

jasonmalinowski commented May 15, 2025

Uh oh!

Uh oh!

ToddGrun commented Apr 25, 2025 •

edited

Loading

ToddGrun commented Apr 29, 2025 •

edited

Loading

ToddGrun commented Apr 29, 2025 •

edited

Loading