Improve build duration logging

- Use IVsUpdateSolutionEvents2 to track build events rather than DTE.
- Handle the case where the "start build" event does not fire. I haven't identified why this occurs, but this change prevents claiming that builds ran for many years.
- Use a System.Diagnostics.Stopwatch for better precision when timing builds. Using DateTime.Now is limited to 15ms granularity, while Stopwatch can do sub-millisecond.
- Wire through the setting that controls time stamp formatting.
- Avoid use of JTF to get onto main thread. We are already on the main thread.

VSColorOutput/Output/BuildEvents/BuildEvents.cs

@@ -1,10 +1,14 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Globalization;
 using System.Threading;
 using EnvDTE;
 using EnvDTE80;
 using Microsoft.VisualStudio;
+using Microsoft.VisualStudio.Shell;
+using Microsoft.VisualStudio.Shell.Interop;
+
 using VSColorOutput.Output.TimeStamp;
 using VSColorOutput.State;
 
@@ -14,19 +18,21 @@
 
 namespace VSColorOutput.Output.BuildEvents
 {
-    public class BuildEvents
+    public class BuildEvents : IVsUpdateSolutionEvents2
     {
+        private readonly Stopwatch _buildDurationStopwatch = new Stopwatch();
+
         private DTE2 _dte2;
         private Events _events;
         private DTEEvents _dteEvents;
         private SolutionEvents _solutionEvents;
-        private EnvDTE.BuildEvents _buildEvents;
         private int _initialized;
-        private DateTime _buildStartTime;
         private List<string> _projectsBuildReport;
+        private IVsSolutionBuildManager2 _sbm;
 
         public bool StopOnBuildErrorEnabled { get; set; }
         public bool ShowElapsedBuildTimeEnabled { get; set; }
+        public string ElapsedTimeFormatString { get; set; }
         public bool ShowBuildReport { get; set; }
         public bool ShowDebugWindowOnDebug { get; set; }
         public bool ShowTimeStamps { get; set; }
@@ -38,6 +44,11 @@ public void Initialize(IServiceProvider serviceProvider)
         {
             if (Interlocked.CompareExchange(ref _initialized, 1, 0) == 1) return;
 
+            _sbm = serviceProvider.GetService<SVsSolutionBuildManager, IVsSolutionBuildManager2>();
+
+            // NOTE this class is never disposed, so we don't track the cookie here and don't unadvise on disposal
+            ErrorHandler.ThrowOnFailure(_sbm.AdviseUpdateSolutionEvents(this, out _));
+
 #pragma warning disable VSSDK006 // Check services exist
             _dte2 = serviceProvider.GetService(typeof(DTE)) as DTE2;
 #pragma warning restore VSSDK006 // Check services exist
@@ -46,13 +57,9 @@ public void Initialize(IServiceProvider serviceProvider)
                 // These event sources have to be rooted or the GC will collect them.
                 // https://social.msdn.microsoft.com/Forums/en-US/vsx/thread/fd2f9108-1df3-4d96-a65d-67a69347ca27
                 _events = _dte2.Events;
-                _buildEvents = _events.BuildEvents;
                 _dteEvents = _events.DTEEvents;
                 _solutionEvents = _events.SolutionEvents;
 
-                _buildEvents.OnBuildBegin += OnBuildBegin;
-                _buildEvents.OnBuildDone += OnBuildDone;
-                _buildEvents.OnBuildProjConfigDone += OnBuildProjectDone;
                 _dteEvents.ModeChanged += OnModeChanged;
 
                 if (_solutionEvents != null)
@@ -79,19 +86,23 @@ private void LoadSettings()
             var settings = Settings.Load();
             StopOnBuildErrorEnabled = settings.EnableStopOnBuildError;
             ShowElapsedBuildTimeEnabled = settings.ShowElapsedBuildTime;
+            ElapsedTimeFormatString = settings.TimeStampElapsed ?? @"hh\:mm\:ss\.fff";
             ShowBuildReport = settings.ShowBuildReport;
             ShowDebugWindowOnDebug = settings.ShowDebugWindowOnDebug;
             ShowTimeStamps = settings.ShowTimeStamps;
             ShowDonation = !settings.SuppressDonation;
         }
 
-        private void OnBuildBegin(vsBuildScope scope, vsBuildAction action)
+        /// <summary>Build is starting.</summary>
+        public int UpdateSolution_Begin(ref int pfCancelUpdate)
         {
             _projectsBuildReport.Clear();
-            _buildStartTime = DateTime.Now;
+            _buildDurationStopwatch.Restart();
+            return VSConstants.S_OK;
         }
 
-        private void OnBuildDone(vsBuildScope scope, vsBuildAction action)
+        /// <summary>Build is complete.</summary>
+        public int UpdateSolution_Done(int fSucceeded, int fModified, int fCancelCommand)
         {
             OutputWindowPane buildOutputPane = null;
             // ReSharper disable once LoopCanBeConvertedToQuery
@@ -106,7 +117,7 @@ private void OnBuildDone(vsBuildScope scope, vsBuildAction action)
 
             if (buildOutputPane == null)
             {
-                return;
+                return VSConstants.S_OK;
             }
 
             if (ShowBuildReport)
@@ -120,12 +131,15 @@ private void OnBuildDone(vsBuildScope scope, vsBuildAction action)
                 }
             }
 
-            if (ShowElapsedBuildTimeEnabled)
+            // Ensure the stop watch has started. A case where the start event hasn't fired has been observed.
+            if (ShowElapsedBuildTimeEnabled && _buildDurationStopwatch.IsRunning)
             {
-                var now = DateTime.Now;
-                var elapsed = now - _buildStartTime;
-                var time = elapsed.ToString(@"hh\:mm\:ss\.fff");
-                var buildTime = now.ToString(CultureInfo.CurrentCulture);
+                // The next build must start it again, so that we don't end up timing across multiple builds.
+                _buildDurationStopwatch.Stop();
+
+                var elapsed = _buildDurationStopwatch.Elapsed;
+                var time = elapsed.ToString(ElapsedTimeFormatString);
+                var buildTime = DateTime.Now.ToString(CultureInfo.CurrentCulture);
                 var timeElapsed = $"Build time {time}";
                 var endedAt = $"Build ended at {buildTime}";
                 buildOutputPane.OutputString($"{Environment.NewLine}{timeElapsed}{Environment.NewLine}");
@@ -140,24 +154,30 @@ private void OnBuildDone(vsBuildScope scope, vsBuildAction action)
                 buildOutputPane.OutputString($"{Environment.NewLine}+++            (this message can be turned off in the settings panel)            +++");
                 buildOutputPane.OutputString($"{Environment.NewLine}++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++{Environment.NewLine}");
             }
+
+            return VSConstants.S_OK;
         }
 
-        private void OnBuildProjectDone(string project, string projectConfig, string platform, string solutionConfig, bool success)
+        /// <summary>A project's build is done.</summary>
+        public int UpdateProjectCfg_Done(IVsHierarchy pHierProj, IVsCfg pCfgProj, IVsCfg pCfgSln, uint dwAction, int fSuccess, int fCancel)
         {
+            bool success = fSuccess != 0;
+
             if (StopOnBuildErrorEnabled && !success)
             {
-                Microsoft.VisualStudio.Shell.ThreadHelper.JoinableTaskFactory.Run(async () =>
-                {
-                    await Microsoft.VisualStudio.Shell.ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync();
-                    const string cancelBuildCommand = "Build.Cancel";
-                    _dte2.ExecuteCommand(cancelBuildCommand);
-                });
+                const string cancelBuildCommand = "Build.Cancel";
+                _dte2.ExecuteCommand(cancelBuildCommand);
             }
 
             if (ShowBuildReport)
             {
-                _projectsBuildReport.Add("  " + (success ? "Succeeded" : "Failed   ") + $" | {project} [{projectConfig}|{platform}]");
+                ErrorHandler.ThrowOnFailure(pHierProj.GetProperty(VSConstants.VSITEMID_ROOT, (int)__VSHPROPID.VSHPROPID_Name, out object project));
+                pCfgProj.get_DisplayName(out string displayName);
+
+                _projectsBuildReport.Add($"  {(success ? "Succeeded" : "Failed   ")} | {project} [{displayName}]");
             }
+
+            return VSConstants.S_OK;
         }
 
         private void OnModeChanged(vsIDEMode lastMode)
@@ -185,5 +205,13 @@ private void ActivateDebugOutputWindow()
                 }
             }
         }
+
+        public int UpdateSolution_StartUpdate(ref int pfCancelUpdate) => VSConstants.S_OK;
+
+        public int UpdateSolution_Cancel() => VSConstants.S_OK;
+
+        public int OnActiveProjectCfgChange(IVsHierarchy pIVsHierarchy) => VSConstants.S_OK;
+
+        public int UpdateProjectCfg_Begin(IVsHierarchy pHierProj, IVsCfg pCfgProj, IVsCfg pCfgSln, uint dwAction, ref int pfCancel) => VSConstants.S_OK;
     }
 }