Start of a PSES log file analyzer

src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs

@@ -110,20 +110,32 @@ public async Task<Message> ReadMessage()
             // Get the JObject for the JSON content
             JObject messageObject = JObject.Parse(messageContent);
 
-            // Load the message
-            this.logger.Write(
-                LogLevel.Diagnostic,
-                string.Format(
-                    "READ MESSAGE:\r\n\r\n{0}",
-                    messageObject.ToString(Formatting.Indented)));
-
-            // Return the parsed message
+            // Deserialize the message from the parsed JSON message
             Message parsedMessage = this.messageSerializer.DeserializeMessage(messageObject);
 
-            this.logger.Write(
-                LogLevel.Verbose,
-                $"Received {parsedMessage.MessageType} '{parsedMessage.Method}'" +
-                (!string.IsNullOrEmpty(parsedMessage.Id) ? $" with id {parsedMessage.Id}" : string.Empty));
+            // Log message info - initial capacity for StringBuilder varies depending on whether
+            // the log level is Diagnostic where JsonRpc message payloads are logged and vary in size
+            // from 1K up to the edited file size.  When not logging message payloads, the typical
+            // request log message size is under 256 chars.
+            var logStrBld =
+                new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 256)
+                   .Append("Received ")
+                   .Append(parsedMessage.MessageType)
+                   .Append(" '").Append(parsedMessage.Method).Append("'");
+
+            if (!string.IsNullOrEmpty(parsedMessage.Id))
+            {
+                logStrBld.Append(" with id ").Append(parsedMessage.Id);
+            }
+
+            if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic)
+            {
+                // Log the JSON representation of the message payload at the Diagnostic log level
+                string jsonPayload = messageObject.ToString(Formatting.Indented);
+                logStrBld.Append(Environment.NewLine).Append(Environment.NewLine).Append(jsonPayload);
+            }
+
+            this.logger.Write(LogLevel.Verbose, logStrBld.ToString());
 
             return parsedMessage;
         }

src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs

@@ -58,20 +58,34 @@ public async Task WriteMessage(Message messageToWrite)
                 this.messageSerializer.SerializeMessage(
                     messageToWrite);
 
-            this.logger.Write(
-                LogLevel.Verbose,
-                $"Writing {messageToWrite.MessageType} '{messageToWrite.Method}'" +
-                (!string.IsNullOrEmpty(messageToWrite.Id) ? $" with id {messageToWrite.Id}" : string.Empty));
-
-            // Log the JSON representation of the message
-            this.logger.Write(
-                LogLevel.Diagnostic,
-                string.Format(
-                    "WRITE MESSAGE:\r\n\r\n{0}",
+            // Log message info - initial capacity for StringBuilder varies depending on whether
+            // the log level is Diagnostic where JsonRpc message payloads are logged and vary
+            // in size from 1K up to 225K chars.  When not logging message payloads, the typical
+            // response log message size is under 256 chars.
+            var logStrBld = 
+                new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 256)
+                   .Append("Writing ")
+                   .Append(messageToWrite.MessageType)
+                   .Append(" '").Append(messageToWrite.Method).Append("'");
+
+            if (!string.IsNullOrEmpty(messageToWrite.Id))
+            {
+                logStrBld.Append(" with id ").Append(messageToWrite.Id);
+            }
+
+            if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic)
+            {
+                // Log the JSON representation of the message payload at the Diagnostic log level
+                string jsonPayload = 
                     JsonConvert.SerializeObject(
                         messageObject,
                         Formatting.Indented,
-                        Constants.JsonSerializerSettings)));
+                        Constants.JsonSerializerSettings);
+
+                logStrBld.Append(Environment.NewLine).Append(Environment.NewLine).Append(jsonPayload);
+            }
+
+            this.logger.Write(LogLevel.Verbose, logStrBld.ToString());
 
             string serializedMessage =
                 JsonConvert.SerializeObject(

src/PowerShellEditorServices/Utility/PsesLogger.cs

@@ -15,7 +15,7 @@ public class PsesLogger : ILogger
         /// The standard log template for all log entries.
         /// </summary>
         private static readonly string s_logMessageTemplate =
-            "[{LogLevelName:l}] tid:{ThreadId} in '{CallerName:l}' {CallerSourceFile:l} (line {CallerLineNumber}):{IndentedLogMsg:l}";
+            "[{LogLevelName:l}] tid:{ThreadId} in '{CallerName:l}' {CallerSourceFile:l}: line {CallerLineNumber}{IndentedLogMsg:l}";
 
         /// <summary>
         /// The name of the ERROR log level.

tools/PsesLogAnalyzer/.vscode/launch.json

@@ -0,0 +1,14 @@
+{
+    // Use IntelliSense to learn about possible attributes.
+    // Hover to view descriptions of existing attributes.
+    // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
+    "version": "0.2.0",
+    "configurations": [
+        {
+            "type": "PowerShell",
+            "request": "launch",
+            "name": "PowerShell Interactive Session",
+            "cwd": ""
+        }
+    ]
+}

tools/PsesLogAnalyzer/Analyze.ps1

@@ -0,0 +1,213 @@
+function Get-PsesRpcNotificationMessage {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry,
+
+        # Specifies a filter for either client or server sourced notifications.  By default both are output.
+        [Parameter()]
+        [ValidateSet('Client', 'Server')]
+        [string]
+        $Source
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            if ($entry.LogMessageType -eq 'Notification') {
+                if (!$Source -or ($entry.Message.Source -eq $Source)) {
+                    $entry
+                }
+            }
+        }
+    }
+}
+
+function Get-PsesRpcMessageResponseTime {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory=$true, Position=0, ParameterSetName="Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory=$true, Position=0, ParameterSetName="PsesLogEntry", ValueFromPipeline=$true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries += $LogEntry
+        }
+    }
+
+    end {
+        # Populate $requests hashtable with request timestamps
+        $requests = @{}
+        $logEntries |
+            Where-Object LogMessageType -match Request |
+            Foreach-Object { $requests[$_.Message.Id] = $_.Timestamp }
+
+        $res = $logEntries |
+            Where-Object LogMessageType -match Response |
+            Foreach-Object {
+                $elapsedMilliseconds = [int]($_.Timestamp - $requests[$_.Message.Id]).TotalMilliseconds
+                [PsesLogEntryElapsed]::new($_, $elapsedMilliseconds)
+            }
+
+        $res
+    }
+}
+
+function Get-PsesScriptAnalysisCompletionTime {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*Script analysis of.*\[(?<ms>\d+)ms\]\s*$')) {
+                $elapsedMilliseconds = [int]$matches["ms"]
+                [PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds)
+            }
+        }
+    }
+}
+
+function Get-PsesIntelliSenseCompletionTime {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            # IntelliSense completed in 320ms.
+            if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*IntelliSense completed in\s+(?<ms>\d+)ms.\s*$')) {
+                $elapsedMilliseconds = [int]$matches["ms"]
+                [PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds)
+            }
+        }
+    }
+}
+
+function Get-PsesMessage {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry,
+
+        # Specifies the log level entries to return.  Default returns Normal and above.
+        # Use StrictMatch to return only the specified log level entries.
+        [Parameter()]
+        [PsesLogLevel]
+        $LogLevel = $([PsesLogLevel]::Normal),
+
+        # Use StrictMatch to return only the specified log level entries.
+        [Parameter()]
+        [switch]
+        $StrictMatch
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            if (($StrictMatch -and ($entry.LogLevel -eq $LogLevel)) -or
+                (!$StrictMatch -and ($entry.LogLevel -ge $LogLevel))) {
+                $entry
+            }
+        }
+    }
+}