[Ignore] Add an easy to use execution timer (#734)

Author: rjmholt

src/PowerShellEditorServices.Protocol/Server/LanguageServer.cs

@@ -1523,11 +1523,10 @@ private static async Task DelayThenInvokeDiagnostics(
                 ScriptFileMarker[] semanticMarkers = null;
                 if (isScriptAnalysisEnabled && editorSession.AnalysisService != null)
                 {
-                    Logger.Write(LogLevel.Verbose, "Analyzing script file: " + scriptFile.FilePath);
-
-                    semanticMarkers = await editorSession.AnalysisService.GetSemanticMarkersAsync(scriptFile);
-
-                    Logger.Write(LogLevel.Verbose, "Analysis complete.");
+                    using (Logger.LogExecutionTime($"Script analysis of {scriptFile.FilePath} completed."))
+                    {
+                        semanticMarkers = await editorSession.AnalysisService.GetSemanticMarkersAsync(scriptFile);
+                    }
                 }
                 else
                 {

src/PowerShellEditorServices/Utility/ExecutionTimer.cs

@@ -0,0 +1,98 @@
+using System;
+using System.Diagnostics;
+using System.Runtime.CompilerServices;
+using System.Text;
+
+namespace Microsoft.PowerShell.EditorServices.Utility
+{
+    /// <summary>
+    /// Simple timer to be used with `using` to time executions.
+    /// </summary>
+    /// <example>
+    /// An example showing how ExecutionTimer is intended to be used
+    /// <code>
+    /// using (ExecutionTimer.Start(logger, "Execution of MyMethod completed."))
+    /// {
+    ///     MyMethod(various, arguments);
+    /// }
+    /// </code>
+    /// This will print a message like "Execution of MyMethod completed. [50ms]" to the logs.
+    /// </example>
+    public struct ExecutionTimer : IDisposable
+    {
+        [ThreadStatic]
+        private static Stopwatch t_stopwatch;
+
+        private readonly ILogger _logger;
+
+        private readonly string _message;
+
+        private readonly string _callerMemberName;
+
+        private readonly string _callerFilePath;
+
+        private readonly int _callerLineNumber;
+
+        /// <summary>
+        /// Create a new execution timer and start it.
+        /// </summary>
+        /// <param name="logger">The logger to log the execution timer message in.</param>
+        /// <param name="message">The message to prefix the execution time with.</param>
+        /// <param name="callerMemberName">The name of the calling method or property.</param>
+        /// <param name="callerFilePath">The path to the source file of the caller.</param>
+        /// <param name="callerLineNumber">The line where the timer is called.</param>
+        /// <returns>A new, started execution timer.</returns>
+        public static ExecutionTimer Start(
+            ILogger logger,
+            string message,
+            [CallerMemberName] string callerMemberName = null,
+            [CallerFilePath] string callerFilePath = null,
+            [CallerLineNumber] int callerLineNumber = -1)
+        {
+            var timer = new ExecutionTimer(logger, message, callerMemberName, callerFilePath, callerLineNumber);
+            t_stopwatch.Start();
+            return timer;
+        }
+
+        internal ExecutionTimer(
+            ILogger logger,
+            string message,
+            string callerMemberName,
+            string callerFilePath,
+            int callerLineNumber)
+        {
+            _logger = logger;
+            _message = message;
+            _callerMemberName = callerMemberName;
+            _callerFilePath = callerFilePath;
+            _callerLineNumber = callerLineNumber;
+        }
+
+        /// <summary>
+        /// Dispose of the execution timer by stopping the stopwatch and then printing
+        /// the elapsed time in the logs.
+        /// </summary>
+        public void Dispose()
+        {
+            t_stopwatch.Stop();
+
+            string logMessage = new StringBuilder()
+                .Append(_message)
+                .Append(" [")
+                .Append(t_stopwatch.ElapsedMilliseconds)
+                .Append("ms]")
+                .ToString();
+
+            t_stopwatch.Reset();
+
+            _logger.Write(
+                LogLevel.Verbose,
+                logMessage,
+                callerName: _callerMemberName,
+                callerSourceFile: _callerFilePath,
+                callerLineNumber: _callerLineNumber);
+        }
+
+        private Stopwatch Stopwatch => t_stopwatch ?? (t_stopwatch = new Stopwatch());
+    }
+}

src/PowerShellEditorServices/Utility/Logging.cs

@@ -239,4 +239,30 @@ private static LogEventLevel ConvertLogLevel(LogLevel logLevel)
             throw new ArgumentException($"Unknown LogLevel: '{logLevel}')", nameof(logLevel));
         }
     }
+
+    /// <summary>
+    /// Extension method class for the ILogger class.
+    /// </summary>
+    public static class ILoggerExtensions
+    {
+        /// <summary>
+        /// Log the amount of time an execution takes. The intended usage is to call this method in the
+        /// header of a `using` block to time the interior of the block.
+        /// </summary>
+        /// <param name="logger">The ILogger to log the execution time with.</param>
+        /// <param name="message">The message to log about what has been executed.</param>
+        /// <param name="callerMemberName">The name of the member calling this method.</param>
+        /// <param name="callerFilePath">The file where this method has been called.</param>
+        /// <param name="callerLineNumber">The line number where this method has been called.</param>
+        /// <returns></returns>
+        public static ExecutionTimer LogExecutionTime(
+            this ILogger logger,
+            string message,
+            [CallerMemberName] string callerMemberName = null,
+            [CallerFilePath] string callerFilePath = null,
+            [CallerLineNumber] int callerLineNumber = -1)
+        {
+            return ExecutionTimer.Start(logger, message, callerMemberName, callerFilePath, callerLineNumber);
+        }
+    }
 }