Skip to content

Commit 65d8e70

Browse files
rkeithhillrkeithhill
authored
Start of a PSES log file analyzer (#797)
* Start of a PSES log file analyzer * Work on parse perf * Add Get-PsesRpcMessageResponseTime command and format file * Address PR feedback - use Env.NewLine, comment strbld capacity * Tweak log message template to separate path from line num with ':' This is probably a legal path char on Linux but on Windows it isn't. Also, Pester uses a similar format: <path>: line <num> Update PSES log analyzer to parse template. Add some more analysis commands. * Change to PsesLogEntry as default parameterset * Address PR feedback, adjust string builder size based on log file data * Address PR feedback - remove unnecessary else
1 parent 9cce6ed commit 65d8e70

File tree

10 files changed

+954
-24
lines changed

10 files changed

+954
-24
lines changed

‎src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs

+24-12
Original file line numberDiff line numberDiff line change
@@ -110,20 +110,32 @@ public async Task<Message> ReadMessage()
110110
// Get the JObject for the JSON content
111111
JObject messageObject = JObject.Parse(messageContent);
112112

113-
// Load the message
114-
this.logger.Write(
115-
LogLevel.Diagnostic,
116-
string.Format(
117-
"READ MESSAGE:\r\n\r\n{0}",
118-
messageObject.ToString(Formatting.Indented)));
119-
120-
// Return the parsed message
113+
// Deserialize the message from the parsed JSON message
121114
Message parsedMessage = this.messageSerializer.DeserializeMessage(messageObject);
122115

123-
this.logger.Write(
124-
LogLevel.Verbose,
125-
$"Received {parsedMessage.MessageType} '{parsedMessage.Method}'" +
126-
(!string.IsNullOrEmpty(parsedMessage.Id) ? $" with id {parsedMessage.Id}" : string.Empty));
116+
// Log message info - initial capacity for StringBuilder varies depending on whether
117+
// the log level is Diagnostic where JsonRpc message payloads are logged and vary in size
118+
// from 1K up to the edited file size. When not logging message payloads, the typical
119+
// request log message size is under 256 chars.
120+
var logStrBld =
121+
new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 256)
122+
.Append("Received ")
123+
.Append(parsedMessage.MessageType)
124+
.Append(" '").Append(parsedMessage.Method).Append("'");
125+
126+
if (!string.IsNullOrEmpty(parsedMessage.Id))
127+
{
128+
logStrBld.Append(" with id ").Append(parsedMessage.Id);
129+
}
130+
131+
if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic)
132+
{
133+
// Log the JSON representation of the message payload at the Diagnostic log level
134+
string jsonPayload = messageObject.ToString(Formatting.Indented);
135+
logStrBld.Append(Environment.NewLine).Append(Environment.NewLine).Append(jsonPayload);
136+
}
137+
138+
this.logger.Write(LogLevel.Verbose, logStrBld.ToString());
127139

128140
return parsedMessage;
129141
}

‎src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs

+25-11
Original file line numberDiff line numberDiff line change
@@ -58,20 +58,34 @@ public async Task WriteMessage(Message messageToWrite)
5858
this.messageSerializer.SerializeMessage(
5959
messageToWrite);
6060

61-
this.logger.Write(
62-
LogLevel.Verbose,
63-
$"Writing {messageToWrite.MessageType} '{messageToWrite.Method}'" +
64-
(!string.IsNullOrEmpty(messageToWrite.Id) ? $" with id {messageToWrite.Id}" : string.Empty));
65-
66-
// Log the JSON representation of the message
67-
this.logger.Write(
68-
LogLevel.Diagnostic,
69-
string.Format(
70-
"WRITE MESSAGE:\r\n\r\n{0}",
61+
// Log message info - initial capacity for StringBuilder varies depending on whether
62+
// the log level is Diagnostic where JsonRpc message payloads are logged and vary
63+
// in size from 1K up to 225K chars. When not logging message payloads, the typical
64+
// response log message size is under 256 chars.
65+
var logStrBld =
66+
new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 256)
67+
.Append("Writing ")
68+
.Append(messageToWrite.MessageType)
69+
.Append(" '").Append(messageToWrite.Method).Append("'");
70+
71+
if (!string.IsNullOrEmpty(messageToWrite.Id))
72+
{
73+
logStrBld.Append(" with id ").Append(messageToWrite.Id);
74+
}
75+
76+
if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic)
77+
{
78+
// Log the JSON representation of the message payload at the Diagnostic log level
79+
string jsonPayload =
7180
JsonConvert.SerializeObject(
7281
messageObject,
7382
Formatting.Indented,
74-
Constants.JsonSerializerSettings)));
83+
Constants.JsonSerializerSettings);
84+
85+
logStrBld.Append(Environment.NewLine).Append(Environment.NewLine).Append(jsonPayload);
86+
}
87+
88+
this.logger.Write(LogLevel.Verbose, logStrBld.ToString());
7589

7690
string serializedMessage =
7791
JsonConvert.SerializeObject(

‎src/PowerShellEditorServices/Utility/PsesLogger.cs

+1-1
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@ public class PsesLogger : ILogger
1515
/// The standard log template for all log entries.
1616
/// </summary>
1717
private static readonly string s_logMessageTemplate =
18-
"[{LogLevelName:l}] tid:{ThreadId} in '{CallerName:l}' {CallerSourceFile:l} (line {CallerLineNumber}):{IndentedLogMsg:l}";
18+
"[{LogLevelName:l}] tid:{ThreadId} in '{CallerName:l}' {CallerSourceFile:l}: line {CallerLineNumber}{IndentedLogMsg:l}";
1919

2020
/// <summary>
2121
/// The name of the ERROR log level.

‎tools/PsesLogAnalyzer/.vscode/launch.json

+14
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,14 @@
1+
{
2+
// Use IntelliSense to learn about possible attributes.
3+
// Hover to view descriptions of existing attributes.
4+
// For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
5+
"version": "0.2.0",
6+
"configurations": [
7+
{
8+
"type": "PowerShell",
9+
"request": "launch",
10+
"name": "PowerShell Interactive Session",
11+
"cwd": ""
12+
}
13+
]
14+
}

‎tools/PsesLogAnalyzer/Analyze.ps1

+213
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,213 @@
1+
function Get-PsesRpcNotificationMessage {
2+
[CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
3+
param(
4+
# Specifies a path to one or more PSES EditorServices log files.
5+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
6+
[Alias("PSPath")]
7+
[ValidateNotNullOrEmpty()]
8+
[string]
9+
$Path,
10+
11+
# Specifies PsesLogEntry objects to analyze.
12+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
13+
[ValidateNotNull()]
14+
[psobject[]]
15+
$LogEntry,
16+
17+
# Specifies a filter for either client or server sourced notifications. By default both are output.
18+
[Parameter()]
19+
[ValidateSet('Client', 'Server')]
20+
[string]
21+
$Source
22+
)
23+
24+
begin {
25+
if ($PSCmdlet.ParameterSetName -eq "Path") {
26+
$logEntries = Parse-PsesLog $Path
27+
}
28+
}
29+
30+
process {
31+
if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
32+
$logEntries = $LogEntry
33+
}
34+
35+
foreach ($entry in $logEntries) {
36+
if ($entry.LogMessageType -eq 'Notification') {
37+
if (!$Source -or ($entry.Message.Source -eq $Source)) {
38+
$entry
39+
}
40+
}
41+
}
42+
}
43+
}
44+
45+
function Get-PsesRpcMessageResponseTime {
46+
[CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
47+
param(
48+
# Specifies a path to one or more PSES EditorServices log files.
49+
[Parameter(Mandatory=$true, Position=0, ParameterSetName="Path")]
50+
[Alias("PSPath")]
51+
[ValidateNotNullOrEmpty()]
52+
[string]
53+
$Path,
54+
55+
# Specifies PsesLogEntry objects to analyze.
56+
[Parameter(Mandatory=$true, Position=0, ParameterSetName="PsesLogEntry", ValueFromPipeline=$true)]
57+
[ValidateNotNull()]
58+
[psobject[]]
59+
$LogEntry
60+
)
61+
62+
begin {
63+
if ($PSCmdlet.ParameterSetName -eq "Path") {
64+
$logEntries = Parse-PsesLog $Path
65+
}
66+
}
67+
68+
process {
69+
if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
70+
$logEntries += $LogEntry
71+
}
72+
}
73+
74+
end {
75+
# Populate $requests hashtable with request timestamps
76+
$requests = @{}
77+
$logEntries |
78+
Where-Object LogMessageType -match Request |
79+
Foreach-Object { $requests[$_.Message.Id] = $_.Timestamp }
80+
81+
$res = $logEntries |
82+
Where-Object LogMessageType -match Response |
83+
Foreach-Object {
84+
$elapsedMilliseconds = [int]($_.Timestamp - $requests[$_.Message.Id]).TotalMilliseconds
85+
[PsesLogEntryElapsed]::new($_, $elapsedMilliseconds)
86+
}
87+
88+
$res
89+
}
90+
}
91+
92+
function Get-PsesScriptAnalysisCompletionTime {
93+
[CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
94+
param(
95+
# Specifies a path to one or more PSES EditorServices log files.
96+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
97+
[Alias("PSPath")]
98+
[ValidateNotNullOrEmpty()]
99+
[string]
100+
$Path,
101+
102+
# Specifies PsesLogEntry objects to analyze.
103+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
104+
[ValidateNotNull()]
105+
[psobject[]]
106+
$LogEntry
107+
)
108+
109+
begin {
110+
if ($PSCmdlet.ParameterSetName -eq "Path") {
111+
$logEntries = Parse-PsesLog $Path
112+
}
113+
}
114+
115+
process {
116+
if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
117+
$logEntries = $LogEntry
118+
}
119+
120+
foreach ($entry in $logEntries) {
121+
if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*Script analysis of.*\[(?<ms>\d+)ms\]\s*$')) {
122+
$elapsedMilliseconds = [int]$matches["ms"]
123+
[PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds)
124+
}
125+
}
126+
}
127+
}
128+
129+
function Get-PsesIntelliSenseCompletionTime {
130+
[CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
131+
param(
132+
# Specifies a path to one or more PSES EditorServices log files.
133+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
134+
[Alias("PSPath")]
135+
[ValidateNotNullOrEmpty()]
136+
[string]
137+
$Path,
138+
139+
# Specifies PsesLogEntry objects to analyze.
140+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
141+
[ValidateNotNull()]
142+
[psobject[]]
143+
$LogEntry
144+
)
145+
146+
begin {
147+
if ($PSCmdlet.ParameterSetName -eq "Path") {
148+
$logEntries = Parse-PsesLog $Path
149+
}
150+
}
151+
152+
process {
153+
if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
154+
$logEntries = $LogEntry
155+
}
156+
157+
foreach ($entry in $logEntries) {
158+
# IntelliSense completed in 320ms.
159+
if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*IntelliSense completed in\s+(?<ms>\d+)ms.\s*$')) {
160+
$elapsedMilliseconds = [int]$matches["ms"]
161+
[PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds)
162+
}
163+
}
164+
}
165+
}
166+
167+
function Get-PsesMessage {
168+
[CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
169+
param(
170+
# Specifies a path to one or more PSES EditorServices log files.
171+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
172+
[Alias("PSPath")]
173+
[ValidateNotNullOrEmpty()]
174+
[string]
175+
$Path,
176+
177+
# Specifies PsesLogEntry objects to analyze.
178+
[Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
179+
[ValidateNotNull()]
180+
[psobject[]]
181+
$LogEntry,
182+
183+
# Specifies the log level entries to return. Default returns Normal and above.
184+
# Use StrictMatch to return only the specified log level entries.
185+
[Parameter()]
186+
[PsesLogLevel]
187+
$LogLevel = $([PsesLogLevel]::Normal),
188+
189+
# Use StrictMatch to return only the specified log level entries.
190+
[Parameter()]
191+
[switch]
192+
$StrictMatch
193+
)
194+
195+
begin {
196+
if ($PSCmdlet.ParameterSetName -eq "Path") {
197+
$logEntries = Parse-PsesLog $Path
198+
}
199+
}
200+
201+
process {
202+
if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
203+
$logEntries = $LogEntry
204+
}
205+
206+
foreach ($entry in $logEntries) {
207+
if (($StrictMatch -and ($entry.LogLevel -eq $LogLevel)) -or
208+
(!$StrictMatch -and ($entry.LogLevel -ge $LogLevel))) {
209+
$entry
210+
}
211+
}
212+
}
213+
}

0 commit comments

Comments
 (0)