Improve exception logging and telemetry for hydration status

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

GVFS/GVFS.Common/GitStatusCache.cs

@@ -356,7 +356,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);
+                    EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, this.context.Tracer);
                 EventMetadata metadata = new EventMetadata();
                 metadata.Add("Area", EtwArea);
                 if (hydrationSummary.IsValid)

GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs

@@ -1,6 +1,8 @@
-using GVFS.Common.FileSystem;
+using GVFS.Common.FileSystem;
 using GVFS.Common.Git;
+using GVFS.Common.Tracing;
 using System;
+using System.Diagnostics;
 using System.IO;
 using System.Linq;
 
@@ -40,27 +42,65 @@ public string ToMessage()
 
         public static EnlistmentHydrationSummary CreateSummary(
             GVFSEnlistment enlistment,
-            PhysicalFileSystem fileSystem)
+            PhysicalFileSystem fileSystem,
+            ITracer tracer)
         {
+            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);
-
-                /* 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. */
-                int totalFolderCount = GetHeadTreeCount(enlistment, fileSystem);
+                long indexReadMs = phaseStopwatch.ElapsedMilliseconds;
 
                 EnlistmentPathData pathData = new EnlistmentPathData();
 
                 /* FUTURE: These could be optimized to only deal with counts instead of full path lists */
+                phaseStopwatch.Restart();
                 pathData.LoadPlaceholdersFromDatabase(enlistment);
-                pathData.LoadModifiedPaths(enlistment);
+                long placeholderLoadMs = phaseStopwatch.ElapsedMilliseconds;
+
+                phaseStopwatch.Restart();
+                pathData.LoadModifiedPaths(enlistment, tracer);
+                long modifiedPathsLoadMs = phaseStopwatch.ElapsedMilliseconds;
 
                 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,
@@ -71,6 +111,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,
@@ -82,6 +123,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);
+        }
+
         /// <summary>
         /// Get the total number of files in the index.
         /// </summary>
@@ -123,12 +187,13 @@ internal static int GetIndexFileCount(GVFSEnlistment enlistment, PhysicalFileSys
         /// The number of subtrees at HEAD, which may be 0.
         /// Will return 0 if unsuccessful.
         /// </returns>
-        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();
@@ -149,8 +214,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
                 }
             }
@@ -161,14 +227,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;

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<string> 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<string> ReadModifiedPathDatabaseLines(StreamReader r)
         /// <remarks>If/when modified paths are moved to SQLite go there instead</remarks>
         /// <param name="enlistment">The enlistment being operated on</param>
         /// <returns>An array containing all of the modified paths in string format</returns>
-        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;
                 }
 

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

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