[Vsintegration] Cut UI-thread marshalling and code model database lock contention - #2084
Open
hpetriffer wants to merge 6 commits into
Open
hpetriffer wants to merge 6 commits into
hpetriffer wants to merge 6 commits into
Conversation
…mation objects OAProjectReference.SourceProject resolved its hierarchy through VsShellUtilities.GetHierarchy on every single read, with no caching, and each read also entered a JoinableTaskFactory.Run that marshals to the UI thread. BuildDependency.GetReferencedHierarchy already cached the same lookup on ProjectInfo.Hierarchy; SourceProject simply ignored it. The intellisense logs show how much that cost: 2,388,244 of these lookups across ~150 logged sessions, 234,360 in a single 11 minute session and 8,928 in one second. Every one is a UI thread marshal, which is what makes the IDE unresponsive while a solution loads. SourceProject now reuses ProjectInfo.Hierarchy and stores the resolved EnvDTE project on the new ProjectInfo.DteProject, shared by every reference node pointing at the same project. Invalidation goes through the existing ProjectInfo lifetime: ClearHierarchy/ClearHierarchies are called from SolutionListenerForProjectReferenceUpdate on project close, unload, reload and solution close. That listener sees every project in the solution, unlike SolutionListenerForProjectEvents which filters to our own hierarchies, so foreign project references are covered too. This also closes a pre-existing hole where BuildDependency could keep using the hierarchy of a foreign project that had been unloaded. Measured on RadixWf.sln (226 projects, 3283 project reference nodes, 88 distinct referenced projects), same scenario before and after, with more editor activity in the after run: OAProjectReference: GetHierarchy 13,183 -> 88 calls (-99.3%) solution wide shell lookups all of them -> 0 load burst wall clock 6.54s -> 2.23s 88 calls over 88 distinct projects, at most one per project, which is the floor. Note that reaching it depends on the ProjectInfo entries already existing when SourceProject is first read; when the build dependency pass runs later instead, this commit alone degrades to repeated lookups. A follow-up commit removes that ordering dependency by registering the entry on demand. Two things to keep in mind when touching this code: - Do not use ReferenceEquals on the hierarchy to decide invalidation. The shell hands out a different runtime callable wrapper for the same project, so comparing wrappers treats almost every write as a change and throws the cache away. DteProject is therefore cleared only when Hierarchy is set to null, which is what the ClearHierarchy methods do. - Store the hierarchy as soon as it is resolved, not only in the branch where the automation object comes back, otherwise later callers pay for the solution wide lookup again. The unload and reload invalidation paths were exercised afterwards by unloading and reloading two heavily referenced projects (AcsDef, 89 referencing projects; AcsLib, 86): ClearHierarchy fires before the rest of the unload handling, OnAfterLoadProject fires on reload, and no COM or other exceptions appear. All measurements are from VS 2022 Experimental. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…rything
The 5 minute backup of the in memory code model database held the global lock
on the connection for its whole duration, and nothing stopped several backups
from queueing up behind each other.
CommitWhenNeeded is called from every write path in XDatabase, and lastWritten
was only updated once SaveToDisk had finished. So every caller inside the 5
minute window still saw a stale timestamp, started its own BackgroundWorker,
and they all serialized on the lock. A cold model walk in August shows the
result: five backups running back to back from 10:00:03 to 10:00:35, half a
minute in which no parse or lookup could touch the code model.
Changes:
- CommitWhenNeeded claims the interval when it schedules the backup instead of
when the backup completes, and an Interlocked guard admits only one at a
time. The guard is the second line of defence for the race where two threads
pass the time check together; the timestamp handles the common case.
- SaveToDisk now takes the lock on oConn only around BackupDatabase, which is
the one call that touches the in memory connection. Deleting the old file,
opening the disk database and the VACUUM all work on the disk side and no
longer block the code model. The lock moved into SaveToDisk so that all four
callers behave the same way; the other three never locked at all.
- SafeFileDelete slept tries*100 ms before even the first attempt, costing
100 ms on every backup for nothing. It now only backs off between retries.
- TimeSpan.Minutes is the minutes component, so "Minutes >= 5 .or. Hours > 0"
was a workaround for the wrong property. Use TotalMinutes.
Measured on a cold walk of RadixWf.sln that rebuilt the whole database
(157,628 parses, 39,387 database writes, 2.6x the write volume of the August
baseline it is compared against):
backups 6 -> 3, no two adjacent (gaps of exactly 300.00s)
total time spent backing up 43.5s -> 12.3s
longest single backup 13.6s -> 5.2s
chained backups 5 in a row -> none
UpdateFileContents lock hold p50 83 -> 58ms, p95 163 -> 105ms,
p99 359 -> 173ms, max 32.5s -> 5.2s
calls holding the lock > 1s 17 -> 3
Note that the comparison is against a historical log from VS 18 rather than a
controlled run of the old code on the same machine, so treat the percentages
as indicative. The elimination of chaining is structural rather than
statistical.
Still open: three unrelated writes held the lock for ~5s simultaneously during
the walk without any backup running, so the lock itself is worth a second look.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…first read
The cache added in the previous commit only works when a ProjectInfo already
exists for the referenced project. ProjectNode.CreateBuildDependencies normally
registers those, but it can run after the automation layer has started reading
SourceProject. When it does there is nowhere to cache: GetProjectInfo returns
null, nothing is stored, and every caller resolves the hierarchy through the
shell again.
That is a race, not a rare case. Two sessions, same solution, same build:
ProjectInfos registered before the reads: 88 calls, 0 shell lookups
ProjectInfos registered after the reads: 4256 calls, 4170 shell lookups
(253 calls for each of 88 projects)
The previous commit was measured on the first of those, so its numbers were a
best case rather than the norm.
ProjectInfo.GetOrCreate registers the entry when it is missing, using the same
(guid, url) pair CreateBuildDependencies would use, so whichever side gets there
first produces an equivalent entry. Guid.Empty is rejected, matching the rule in
ProjectNode that avoids registering a url keyed entry before the guid is known.
Two threads racing produce two equivalent entries and the last one wins, costing
at most one extra resolution.
Verified over three open / unload / reload / close cycles in one session:
86 of 88 projects resolved exactly once per cycle
shell lookups 88, 92, 92 - stable, no ordering dependency left
no growth across cycles (268, 268 calls; ProjectInfo create/remove 78/78)
no cycle below 88 resolutions, so entries really are invalidated on solution
close rather than carried into the next solution
0 errors
The calls above 88 in later cycles all belong to the two projects that were
unloaded: while a project is unloaded its hierarchy is a stub whose
VSHPROPID_ExtObject is not an EnvDTE.Project, so there is nothing to cache and
each referencing node re-enters once. The expensive part stays cached - shell
lookups rose by 4, not by 180 - and it lasts only as long as the project is
unloaded.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…per file UpdateFileContents ran Delete from IncludeFiles where Id not in (select IdInclude from IncludeFilesPerFile) for every file it wrote, inside the lock that serializes the whole code model. That is a full anti join over IncludeFilesPerFile, and a cold walk of RadixWf.sln does it 39387 times. It was redundant as well: DeleteOrphanFiles() already runs the identical statement in bulk when the database is opened. The statement moves to a new DeleteOrphanIncludeFiles(), called once per project walk from ModelWalker after the pass that drops files which no longer exist on disk. Orphan rows are harmless until they are collected: nothing reads them, and UpdateIncludeFiles reuses an existing row when the include comes back. Measured with two cold walks on the same machine and solution, doing practically identical work (39,387 vs 39,380 writes, 157,628 vs 157,568 parses): total time holding the lock 2088s -> 1020s (-51%) p50 per write 58ms -> 28ms p95 105ms -> 52ms p99 173ms -> 68ms worst single write 5164ms -> 394ms (-92%) writes holding the lock > 1s 3 -> 0 orphan sweeps 39387 -> 98 (one per project walk) So the anti join, not AddTypes or WriteLocalFunctions, was what made the critical section expensive. It also explains the three ~5s holds that happened simultaneously in an earlier walk with no backup running: that was this statement, not threads queueing for the lock. This does not change the shape of the problem. There is still one lock around one connection, with ModelWalker running Parallel.ForEach at 3/4 of the cores straight into it, and XDatabase.Read(XFile) is still called 4.8 times per file on average (217,921 calls over 45,492 distinct files in one session, 793 of them for builtinfunctions.prg alone). That one is left alone on purpose: Read also inserts the row when it is missing and refreshes Id, LastChanged and Size, and it has seven call sites, so a naive "skip when Id is set" guard could stop changes on disk from being noticed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…nsaction There were no transactions anywhere in XDatabase, so every statement ran as its own implicit transaction. AddTypes issues an INSERT per type and AddMembers one per member, which for a file with 159 entities is around 160 of them, and a cold walk of RadixWf.sln writes 39,380 files. All of it happens inside the lock that serializes the whole code model. UpdateFileContents now wraps its work in BEGIN IMMEDIATE / COMMIT, with a ROLLBACK in a FINALLY so a failed file cannot leave the connection sitting in a transaction for the next one. BEGIN and COMMIT are sent as plain SQL rather than through DbTransaction on purpose. A DbTransaction would have to be assigned to every command created further down the call chain - AddTypes, AddMembers, WriteLocalFunctions, WriteCommentTasks, UpdateIncludeFiles - and Microsoft.Data.Sqlite throws when a command misses it. Since the code builds against both System.Data.SQLite and Microsoft.Data.Sqlite, the plain statements are the safer form. Two cold walks doing identical work (39,380 writes, 157,568 vs 157,576 parses, both producing a 169 MB database, no errors in either): total time holding the lock 1020s -> 197s (-81%) p50 per write 28ms -> 3ms p95 52ms -> 15ms p99 68ms -> 42ms worst single write 394ms -> 265ms mean per write 25.9ms -> 5.0ms Together with the two preceding commits that is 2088s -> 197s of lock time for the same walk, and a worst case of 265ms where it used to be 5164ms. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…er saved file XFile.SaveToDatabase() called Project:RefreshGlobalUsings() after every file it wrote, and that method runs XDatabase.GetProjectGlobalUsings() - a query taking the lock that serializes the code model. A cold walk of RadixWf.sln writes 39,380 files, so it ran 39,380 times, for a list that changes rarely. SaveToDatabase now only marks the lists stale, which costs nothing, and they are rebuilt on the first read through the GlobalUsings / GlobalStaticUsings properties. Two related corrections while in there: - RefreshGlobalUsings built its result by clearing the live lists and refilling them. The walker writes from several threads at once, so a reader iterating GlobalUsings could see the list half emptied. It now builds new lists and swaps them in. - The dirty flag starts TRUE. The only thing that ever populated these lists was a file save, so opening a solution against an up to date database, where no file needs writing, left them empty. Now the first reader fills them. Not separately measured: RefreshGlobalUsings ran after XDatabase.Update returned, so its cost falls outside the Start/End Updating File contents window used to measure the previous commit. It contributed to wall clock and to lock contention, but the walk that went from 6.5 to 2.8 minutes contains both changes and the log has no counter for GetProjectGlobalUsings to separate them. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
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.
Six changes to the VS integration, each measured against a before/after run on the same machine. They fall into two groups: how project references are resolved through the automation API, and how the code model database is written.
Everything started from the intellisense logs of ~150 real sessions, which pointed somewhere unexpected: the file-open pipeline itself is fast and does not degrade with session age (
ParseAsyncp50 stays 13-31 ms from minute 0 to hour 4, colorization 1-13 ms). What makes the IDE feel slow is UI-thread marshalling and lock contention from other subsystems.Project references
OAProjectReference.SourceProjectresolved its hierarchy on every read, throughVsShellUtilities.GetHierarchy, with no caching, each read inside aJoinableTaskFactory.Runthat marshals to the UI thread.BuildDependency.GetReferencedHierarchyalready cached exactly that lookup onProjectInfo.Hierarchy;SourceProjectignored it.The logs show 2,388,244 of these lookups across ~150 sessions - 234,360 in a single 11-minute session, 8,928 in one second.
It now reuses
ProjectInfo.Hierarchyand caches the resolvedEnvDTE.Projecton a newProjectInfo.DteProject, shared by every reference node pointing at the same project. Invalidation goes through the existingProjectInfolifetime, driven fromSolutionListenerForProjectReferenceUpdateon project close, unload, reload and solution close. That listener sees every project in the solution, unlikeSolutionListenerForProjectEventswhich filters to our own hierarchies - so foreign project references are covered too. That also closes a pre-existing hole whereBuildDependencycould keep using the hierarchy of an unloaded foreign project.A separate commit makes
SourceProjectregister theProjectInfowhen it is missing. Without that, the cache only worked whenCreateBuildDependencieshappened to run first, and the difference was large: two sessions on the same solution with identical code gave 88 calls / 0 shell lookups and 4,256 calls / 4,170 shell lookups.On
RadixWf.sln(226 projects, 3,283 project reference nodes, 88 distinct referenced projects):GetHierarchycalls on solution loadCode model database
The database is a single in-memory SQLite connection behind one global lock. Three things were happening inside it that did not need to be.
Backups chained.
CommitWhenNeededis called from every write path but only updatedlastWrittenonceSaveToDiskhad finished, so every caller inside the 5-minute window queued its ownBackgroundWorkerand they serialized on the lock. One August session shows five backups running back to back, 10:00:03 to 10:00:35 - half a minute with the code model unavailable. The interval is now claimed when the backup is scheduled, with anInterlockedguard behind it, and the lock is held only aroundBackupDatabaseinstead of around the file delete, theOpenFileand theVACUUMas well.SafeFileDeletealso slept 100 ms before its first attempt, on every backup.A per-file orphan sweep.
UpdateFileContentsranDelete from IncludeFiles where Id not in (select IdInclude from IncludeFilesPerFile)- a full anti-join - for every file written, 39,380 times in a cold walk, and redundant with the bulkDeleteOrphanFiles()that already runs at database open. Now once per project walk.No transactions at all. Every statement was its own implicit transaction, and
AddTypes/AddMembersissue one INSERT per type and per member (~160 for a 159-entity file).UpdateFileContentsnow wraps its work inBEGIN IMMEDIATE/COMMITwith aROLLBACKin aFINALLY. These are sent as plain SQL rather than viaDbTransactionon purpose: aDbTransactionwould have to be assigned to every command created down the call chain, and Microsoft.Data.Sqlite throws when one misses it - and this builds against both providers.Plus
XFile.SaveToDatabase()calledRefreshGlobalUsings()- a query - after every single file. It now marks the lists stale and they rebuild on first read.Cold walk of
RadixWf.sln, 39,380 file writes in every run:Two corrections made along the way
RefreshGlobalUsingsbuilt its result by clearing the live lists and refilling them, while the walker writes from several threads - a reader could see the list half emptied. It now builds new lists and swaps them in. And its dirty flag startsTRUE, because previously the only thing that ever populated those lists was a file save, so opening a solution against an up-to-date database left them empty.What has and has not been verified
Verified: the unload/reload invalidation, over three open/unload/reload/close cycles - 86 of 88 projects resolve exactly once per cycle, no growth across cycles, and never below 88 per cycle, which would have meant stale entries surviving into the next solution. No errors in any run. The rebuilt database is byte-comparable in size across before/after walks.
Please be aware of the limits:
EnvDTE.Projectacross reference nodes was suspected of causing VS crashes during testing and then cleared - four crash dumps all showedFileNotFoundException: AcsLibon the finalizer thread viaComponent.Finalize(), reproduced on unmodifieddevwith the changes stashed out. But it has not been positively proven safe against every automation consumer, and a maintainer may know of consumers I do not.One thing worth fixing separately, because it makes this area hard to profile:
Logger.StartAsync()callsXSettings.EnableAll(), andIntellisenseOptions.WriteToSettings()then copies the option-page defaults straight over it. In a fresh experimental hive that silently disables database and parser logging, which is easy to misread as "the work never ran".🤖 Generated with Claude Code