From 403dc23f9891d1710fe5f0d24fb7b437299c2cdc Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Thu, 18 Jun 2026 17:05:20 -0700 Subject: [PATCH] Add telemetry events to mount initialization phases MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Emit Keywords.Telemetry events at each phase transition during mount so that slow or hung mounts can be diagnosed from server-side telemetry. Previously, there was a telemetry gap between VFS.EnlistmentInfo and VFS.Mount 'Virtual repo is ready' — if any intermediate phase stalled, no Application Insights events were recorded. New MountPhase events with elapsed-since-mount-start timestamps: - ParallelMountStarted: parallel auth+local validation begins - NetworkValidationComplete: auth + /gvfs/config query done (duration) - LocalValidationComplete: git/hooks/fs validation + config done (duration) - ParallelMountComplete: both parallel tasks finished - CacheServerResolved: cache server URL resolved - LocalCacheHealthy: local object cache validated - ContextCreated: GVFSContext initialized - HooksUpdated: hook binaries installed (or skipped for worktrees) - VirtualizationStarting: about to start ProjFS callbacks Note: RetryConfig defaults are 6 retries x 30s timeout = 210s worst case for the network task. When auth is expired/stuck, the mount can block for up to 210s in TryInitializeAndQueryGVFSConfig with no telemetry — these new events make that visible. Assisted-by: Claude Opus 4.6 Signed-off-by: Tyrie Vella --- GVFS/GVFS.Mount/InProcessMount.cs | 110 ++++++++++++++++++++++++++++++ 1 file changed, 110 insertions(+) diff --git a/GVFS/GVFS.Mount/InProcessMount.cs b/GVFS/GVFS.Mount/InProcessMount.cs index 1896d21f6..2123532a6 100644 --- a/GVFS/GVFS.Mount/InProcessMount.cs +++ b/GVFS/GVFS.Mount/InProcessMount.cs @@ -128,8 +128,19 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) // TryInitializeAndQueryGVFSConfig combines the anonymous probe, credential fetch, // and config query into at most 2 HTTP requests (1 for anonymous repos), reusing // the same HttpClient/TCP connection. + Stopwatch mountPhaseTimer = Stopwatch.StartNew(); Stopwatch parallelTimer = Stopwatch.StartNew(); + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "ParallelMountStarted" }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + var networkTask = Task.Run(() => { Stopwatch sw = Stopwatch.StartNew(); @@ -155,6 +166,18 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) } this.ValidateGVFSVersion(config); + + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "NetworkValidationComplete" }, + { "DurationMs", sw.ElapsedMilliseconds }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + this.tracer.RelatedInfo("ParallelMount: Auth + config completed in {0}ms", sw.ElapsedMilliseconds); return config; }); @@ -237,6 +260,18 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) } this.LogEnlistmentInfoAndSetConfigValues(); + + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "LocalValidationComplete" }, + { "DurationMs", sw.ElapsedMilliseconds }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + this.tracer.RelatedInfo("ParallelMount: Local validations + git config completed in {0}ms", sw.ElapsedMilliseconds); }); @@ -252,17 +287,59 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) parallelTimer.Stop(); this.tracer.RelatedInfo("ParallelMount: All parallel tasks completed in {0}ms", parallelTimer.ElapsedMilliseconds); + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "ParallelMountComplete" }, + { "DurationMs", parallelTimer.ElapsedMilliseconds }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + ServerGVFSConfig serverGVFSConfig = networkTask.Result; this.mountProgressMessage = "Resolving cache server"; CacheServerResolver cacheServerResolver = new CacheServerResolver(this.tracer, this.enlistment); this.cacheServer = cacheServerResolver.ResolveNameFromRemote(this.cacheServer.Url, serverGVFSConfig); + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "CacheServerResolved" }, + { "CacheServerUrl", this.cacheServer.Url ?? string.Empty }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + this.EnsureLocalCacheIsHealthy(serverGVFSConfig); + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "LocalCacheHealthy" }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + this.mountProgressMessage = "Preparing mount"; this.context = this.CreateContext(); + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "ContextCreated" }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + if (this.context.Unattended) { this.tracer.RelatedEvent(EventLevel.Critical, GVFSConstants.UnattendedEnvironmentVariable, null); @@ -279,11 +356,43 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) this.FailMountAndExit(errorMessage); } + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "HooksUpdated" }, + { "Skipped", this.enlistment.IsWorktree }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + GVFSPlatform.Instance.ConfigureVisualStudio(this.enlistment.GitBinPath, this.tracer); this.mountProgressMessage = "Starting virtualization"; + + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "VirtualizationStarting" }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + this.MountAndStartWorkingDirectoryCallbacks(this.cacheServer); + this.tracer.RelatedEvent( + EventLevel.Informational, + "MountPhase", + new EventMetadata + { + { "Phase", "VirtualizationComplete" }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, + }, + Keywords.Telemetry); + try { Console.Title = "GVFS " + ProcessHelper.GetCurrentProcessVersion() + " - " + this.enlistment.WorkingDirectoryRoot; @@ -301,6 +410,7 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) // Use TracingConstants.MessageKey.InfoMessage rather than TracingConstants.MessageKey.CriticalMessage // as this message should not appear as an error { TracingConstants.MessageKey.InfoMessage, "Virtual repo is ready" }, + { "ElapsedMs", mountPhaseTimer.ElapsedMilliseconds }, }, Keywords.Telemetry);