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);