diff --git a/GVFS/GVFS.Common/GVFSConstants.cs b/GVFS/GVFS.Common/GVFSConstants.cs index cf52e1fbb..8f428ddb9 100644 --- a/GVFS/GVFS.Common/GVFSConstants.cs +++ b/GVFS/GVFS.Common/GVFSConstants.cs @@ -99,6 +99,7 @@ public static class LogFileTypes public const string Clone = "clone"; public const string Dehydrate = "dehydrate"; + public const string Health = "health"; public const string MountVerb = MountPrefix + "_verb"; public const string MountProcess = MountPrefix + "_process"; public const string MountUpgrade = MountPrefix + "_repoupgrade"; diff --git a/GVFS/GVFS.Common/GitStatusCache.cs b/GVFS/GVFS.Common/GitStatusCache.cs index 30bbc7bce..296a00160 100644 --- a/GVFS/GVFS.Common/GitStatusCache.cs +++ b/GVFS/GVFS.Common/GitStatusCache.cs @@ -400,7 +400,7 @@ private void UpdateHydrationSummary() * and this is also a convenient place to log telemetry for it. */ EnlistmentHydrationSummary hydrationSummary = - EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, cancellationToken: this.shutdownTokenSource.Token); + EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, this.context.Tracer, cancellationToken: this.shutdownTokenSource.Token); EventMetadata metadata = new EventMetadata(); metadata.Add("Area", EtwArea); if (hydrationSummary.IsValid) diff --git a/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs b/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs index 74802541e..10f72a555 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs @@ -1,6 +1,8 @@ using GVFS.Common.FileSystem; using GVFS.Common.Git; +using GVFS.Common.Tracing; using System; +using System.Diagnostics; using System.IO; using System.Linq; using System.Threading; @@ -41,35 +43,72 @@ public string ToMessage() public static EnlistmentHydrationSummary CreateSummary( GVFSEnlistment enlistment, - PhysicalFileSystem fileSystem, + PhysicalFileSystem fileSystem, + ITracer tracer, CancellationToken cancellationToken = default) { + Stopwatch totalStopwatch = Stopwatch.StartNew(); + Stopwatch phaseStopwatch = new Stopwatch(); + try { /* Getting all the file paths from git index is slow and we only need the total count, * so we read the index file header instead of calling GetPathsFromGitIndex */ + phaseStopwatch.Restart(); int totalFileCount = GetIndexFileCount(enlistment, fileSystem); + long indexReadMs = phaseStopwatch.ElapsedMilliseconds; - /* Getting all the directories is also slow, but not as slow as reading the entire index, - * GetTotalPathCount caches the count so this is only slow occasionally, - * and the GitStatusCache manager also calls this to ensure it is updated frequently. */ - cancellationToken.ThrowIfCancellationRequested(); - int totalFolderCount = GetHeadTreeCount(enlistment, fileSystem); + cancellationToken.ThrowIfCancellationRequested(); EnlistmentPathData pathData = new EnlistmentPathData(); /* FUTURE: These could be optimized to only deal with counts instead of full path lists */ + phaseStopwatch.Restart(); pathData.LoadPlaceholdersFromDatabase(enlistment); - - cancellationToken.ThrowIfCancellationRequested(); - - pathData.LoadModifiedPaths(enlistment); + long placeholderLoadMs = phaseStopwatch.ElapsedMilliseconds; + + cancellationToken.ThrowIfCancellationRequested(); + + phaseStopwatch.Restart(); + pathData.LoadModifiedPaths(enlistment, tracer); + long modifiedPathsLoadMs = phaseStopwatch.ElapsedMilliseconds; - cancellationToken.ThrowIfCancellationRequested(); int hydratedFileCount = pathData.ModifiedFilePaths.Count + pathData.PlaceholderFilePaths.Count; int hydratedFolderCount = pathData.ModifiedFolderPaths.Count + pathData.PlaceholderFolderPaths.Count; + + /* Getting the head tree count (used for TotalFolderCount) is potentially slower than the other parts + * of the operation, so we do it last and check that the other parts would succeed before running it. + */ + var soFar = new EnlistmentHydrationSummary() + { + HydratedFileCount = hydratedFileCount, + HydratedFolderCount = hydratedFolderCount, + TotalFileCount = totalFileCount, + TotalFolderCount = hydratedFolderCount + 1, // Not calculated yet, use a dummy valid value. + }; + + if (!soFar.IsValid) + { + soFar.TotalFolderCount = 0; // Set to default invalid value to avoid confusion with the dummy value above. + tracer.RelatedWarning( + $"Hydration summary early exit: data invalid before tree count. " + + $"TotalFileCount={totalFileCount}, HydratedFileCount={hydratedFileCount}, " + + $"HydratedFolderCount={hydratedFolderCount}"); + EmitDurationTelemetry(tracer, totalStopwatch.ElapsedMilliseconds, indexReadMs, placeholderLoadMs, modifiedPathsLoadMs, treeCountMs: 0, earlyExit: true); + return soFar; + } + + /* Getting all the directories is also slow, but not as slow as reading the entire index, + * GetTotalPathCount caches the count so this is only slow occasionally, + * and the GitStatusCache manager also calls this to ensure it is updated frequently. */ + phaseStopwatch.Restart(); + int totalFolderCount = GetHeadTreeCount(enlistment, fileSystem, tracer); + long treeCountMs = phaseStopwatch.ElapsedMilliseconds; + + EmitDurationTelemetry(tracer, totalStopwatch.ElapsedMilliseconds, indexReadMs, placeholderLoadMs, modifiedPathsLoadMs, treeCountMs, earlyExit: false); + return new EnlistmentHydrationSummary() { HydratedFileCount = hydratedFileCount, @@ -90,6 +129,7 @@ public static EnlistmentHydrationSummary CreateSummary( } catch (Exception e) { + tracer.RelatedError($"Hydration summary failed with exception after {totalStopwatch.ElapsedMilliseconds}ms: {e.Message}"); return new EnlistmentHydrationSummary() { HydratedFileCount = -1, @@ -101,6 +141,29 @@ public static EnlistmentHydrationSummary CreateSummary( } } + private static void EmitDurationTelemetry( + ITracer tracer, + long totalMs, + long indexReadMs, + long placeholderLoadMs, + long modifiedPathsLoadMs, + long treeCountMs, + bool earlyExit) + { + EventMetadata metadata = new EventMetadata(); + metadata["TotalMs"] = totalMs; + metadata["IndexReadMs"] = indexReadMs; + metadata["PlaceholderLoadMs"] = placeholderLoadMs; + metadata["ModifiedPathsLoadMs"] = modifiedPathsLoadMs; + metadata["TreeCountMs"] = treeCountMs; + metadata["EarlyExit"] = earlyExit; + tracer.RelatedEvent( + EventLevel.Informational, + "HydrationSummaryDuration", + metadata, + Keywords.Telemetry); + } + /// /// Get the total number of files in the index. /// @@ -142,12 +205,13 @@ internal static int GetIndexFileCount(GVFSEnlistment enlistment, PhysicalFileSys /// The number of subtrees at HEAD, which may be 0. /// Will return 0 if unsuccessful. /// - internal static int GetHeadTreeCount(GVFSEnlistment enlistment, PhysicalFileSystem fileSystem) + internal static int GetHeadTreeCount(GVFSEnlistment enlistment, PhysicalFileSystem fileSystem, ITracer tracer) { var gitProcess = enlistment.CreateGitProcess(); var headResult = gitProcess.GetHeadTreeId(); if (headResult.ExitCodeIsFailure) { + tracer.RelatedError($"Failed to get HEAD tree ID: \nOutput: {headResult.Output}\n\nError:{headResult.Errors}"); return 0; } var headSha = headResult.Output.Trim(); @@ -168,8 +232,9 @@ internal static int GetHeadTreeCount(GVFSEnlistment enlistment, PhysicalFileSyst return cachedCount; } } - catch + catch (Exception ex) { + tracer.RelatedWarning($"Failed to read tree count cache file at {cacheFile}: {ex}"); // Ignore errors reading the cache } } @@ -180,14 +245,22 @@ internal static int GetHeadTreeCount(GVFSEnlistment enlistment, PhysicalFileSyst line => totalPathCount++, recursive: true, showDirectories: true); + + if (GitProcess.Result.SuccessCode != folderResult.ExitCode) + { + tracer.RelatedError($"Failed to get tree count from HEAD: \nOutput: {folderResult.Output}\n\nError:{folderResult.Errors}"); + return 0; + } + try { fileSystem.CreateDirectory(Path.GetDirectoryName(cacheFile)); fileSystem.WriteAllText(cacheFile, $"{headSha}\n{totalPathCount}"); } - catch + catch (Exception ex) { // Ignore errors writing the cache + tracer.RelatedWarning($"Failed to write tree count cache file at {cacheFile}: {ex}"); } return totalPathCount; diff --git a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs index 911b3f805..8a6df6818 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs @@ -2,6 +2,7 @@ using GVFS.Common.FileSystem; using GVFS.Common.Git; using GVFS.Common.NamedPipes; +using GVFS.Common.Tracing; using System; using System.Collections.Generic; using System.IO; @@ -94,30 +95,39 @@ public void LoadPathsFromGitIndex(GVFSEnlistment enlistment) this.GitTrackingPaths.AddRange(skipWorktreeFiles); } - public void LoadModifiedPaths(GVFSEnlistment enlistment) + public void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer) { - if (TryLoadModifiedPathsFromPipe(enlistment)) + if (TryLoadModifiedPathsFromPipe(enlistment, tracer)) { return; } + + // Most likely GVFS is not mounted. Give a basic effort to read the modified paths database. + string filePath = Path.Combine(enlistment.DotGVFSRoot, GVFSConstants.DotGVFS.Databases.ModifiedPaths); try { - /* Most likely GVFS is not mounted. Give a basic effort to read the modified paths database */ - var filePath = Path.Combine(enlistment.DotGVFSRoot, GVFSConstants.DotGVFS.Databases.ModifiedPaths); - using (var file = File.Open(filePath, FileMode.OpenOrCreate, FileAccess.Read, FileShare.Read)) - using (var reader = new StreamReader(file)) + using (FileStream file = File.Open(filePath, FileMode.OpenOrCreate, FileAccess.Read, FileShare.Read)) + using (StreamReader reader = new StreamReader(file)) { AddModifiedPaths(ReadModifiedPathDatabaseLines(reader)); } } - catch { } + catch (Exception ex) + { + tracer.RelatedWarning($"Failed to read modified paths file at {filePath}: {ex.Message}"); + } } private IEnumerable ReadModifiedPathDatabaseLines(StreamReader r) { while (!r.EndOfStream) { - var line = r.ReadLine(); + string line = r.ReadLine(); + if (line == null) + { + continue; + } + const string LinePrefix = "A "; if (line.StartsWith(LinePrefix)) { @@ -133,7 +143,7 @@ private IEnumerable ReadModifiedPathDatabaseLines(StreamReader r) /// If/when modified paths are moved to SQLite go there instead /// The enlistment being operated on /// An array containing all of the modified paths in string format - private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment) + private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment, ITracer tracer) { using (NamedPipeClient pipeClient = new NamedPipeClient(enlistment.NamedPipeName)) { @@ -157,8 +167,9 @@ private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment) modifiedPathsList = modifiedPathsResponse.Body.Split(new char[] { '\0' }, StringSplitOptions.RemoveEmptyEntries); } - catch (BrokenPipeException e) + catch (Exception ex) { + tracer.RelatedWarning($"Failed to load modified paths via named pipe: {ex.Message}"); return false; } diff --git a/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs b/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs index 2623dc4bd..f826c4359 100644 --- a/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs +++ b/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs @@ -112,7 +112,7 @@ public void HeadTreeCountCacheTests((string CachePrecontents, string ExpectedCac args.CachePrecontents != null, this.fileSystem.FileExists(totalPathCountPath)); - int result = EnlistmentHydrationSummary.GetHeadTreeCount(this.context.Enlistment, this.context.FileSystem); + int result = EnlistmentHydrationSummary.GetHeadTreeCount(this.context.Enlistment, this.context.FileSystem, this.context.Tracer); this.fileSystem.FileExists(totalPathCountPath).ShouldBeTrue(); var postContents = this.fileSystem.ReadAllText(totalPathCountPath); diff --git a/GVFS/GVFS/CommandLine/HealthVerb.cs b/GVFS/GVFS/CommandLine/HealthVerb.cs index 782c014c2..897bc23d7 100644 --- a/GVFS/GVFS/CommandLine/HealthVerb.cs +++ b/GVFS/GVFS/CommandLine/HealthVerb.cs @@ -1,6 +1,7 @@ using CommandLine; using GVFS.Common; using GVFS.Common.FileSystem; +using GVFS.Common.Tracing; using System; using System.Collections.Generic; using System.Linq; @@ -39,47 +40,55 @@ public class HealthVerb : GVFSVerb.ForExistingEnlistment protected override void Execute(GVFSEnlistment enlistment) { - if (this.StatusOnly) + using (JsonTracer tracer = new JsonTracer(GVFSConstants.GVFSEtwProviderName, HealthVerbName)) { - this.OutputHydrationPercent(enlistment); - return; - } + tracer.AddLogFileEventListener( + GVFSEnlistment.GetNewGVFSLogFileName(enlistment.GVFSLogsRoot, GVFSConstants.LogFileTypes.Health), + EventLevel.Informational, + Keywords.Any); - // Now default to the current working directory when running the verb without a specified path - if (string.IsNullOrEmpty(this.Directory) || this.Directory.Equals(".")) - { - if (Environment.CurrentDirectory.StartsWith(enlistment.WorkingDirectoryRoot, GVFSPlatform.Instance.Constants.PathComparison)) + if (this.StatusOnly) { - this.Directory = Environment.CurrentDirectory.Substring(enlistment.WorkingDirectoryRoot.Length); + this.OutputHydrationPercent(enlistment, tracer); + return; } - else + + // Now default to the current working directory when running the verb without a specified path + if (string.IsNullOrEmpty(this.Directory) || this.Directory.Equals(".")) { - // If the path is not under the source root, set the directory to empty - this.Directory = string.Empty; + if (Environment.CurrentDirectory.StartsWith(enlistment.WorkingDirectoryRoot, GVFSPlatform.Instance.Constants.PathComparison)) + { + this.Directory = Environment.CurrentDirectory.Substring(enlistment.WorkingDirectoryRoot.Length); + } + else + { + // If the path is not under the source root, set the directory to empty + this.Directory = string.Empty; + } } - } - this.Output.WriteLine("\nGathering repository data..."); + this.Output.WriteLine("\nGathering repository data..."); - this.Directory = this.Directory.Replace(GVFSPlatform.GVFSPlatformConstants.PathSeparator, GVFSConstants.GitPathSeparator); + this.Directory = this.Directory.Replace(GVFSPlatform.GVFSPlatformConstants.PathSeparator, GVFSConstants.GitPathSeparator); - EnlistmentPathData pathData = new EnlistmentPathData(); + EnlistmentPathData pathData = new EnlistmentPathData(); - pathData.LoadPlaceholdersFromDatabase(enlistment); - pathData.LoadModifiedPaths(enlistment); - pathData.LoadPathsFromGitIndex(enlistment); + pathData.LoadPlaceholdersFromDatabase(enlistment); + pathData.LoadModifiedPaths(enlistment, tracer); + pathData.LoadPathsFromGitIndex(enlistment); - pathData.NormalizeAllPaths(); + pathData.NormalizeAllPaths(); - EnlistmentHealthCalculator enlistmentHealthCalculator = new EnlistmentHealthCalculator(pathData); - EnlistmentHealthData enlistmentHealthData = enlistmentHealthCalculator.CalculateStatistics(this.Directory); + EnlistmentHealthCalculator enlistmentHealthCalculator = new EnlistmentHealthCalculator(pathData); + EnlistmentHealthData enlistmentHealthData = enlistmentHealthCalculator.CalculateStatistics(this.Directory); - this.PrintOutput(enlistmentHealthData); + this.PrintOutput(enlistmentHealthData); + } } - private void OutputHydrationPercent(GVFSEnlistment enlistment) + private void OutputHydrationPercent(GVFSEnlistment enlistment, ITracer tracer) { - var summary = EnlistmentHydrationSummary.CreateSummary(enlistment, this.FileSystem); + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary(enlistment, this.FileSystem, tracer); this.Output.WriteLine(summary.ToMessage()); }