Skip to content

Commit 0230b1d

Browse files
rkeithhillrkeithhill
committed
Add Get-PsesRpcMessageResponseTime command and format file
1 parent f40bd86 commit 0230b1d

File tree

7 files changed

+354
-127
lines changed

7 files changed

+354
-127
lines changed

‎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

+46
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,46 @@
1+
function Get-PsesRpcMessageResponseTime {
2+
[CmdletBinding(DefaultParameterSetName="Path")]
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+
18+
begin {
19+
if ($PSCmdlet.ParameterSetName -eq "Path") {
20+
$logEntries = Parse-PsesLog $Path
21+
}
22+
}
23+
24+
process {
25+
if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
26+
$logEntries += $LogEntry
27+
}
28+
}
29+
30+
end {
31+
# Populate $requests hashtable with request timestamps
32+
$requests = @{}
33+
$logEntries |
34+
Where-Object MessageType -match Request |
35+
Foreach-Object { $requests[$_.Message.Id] = $_.Timestamp }
36+
37+
$res = $logEntries |
38+
Where-Object MessageType -match Response |
39+
Foreach-Object {
40+
$elapsedMilliseconds = [int]($_.Timestamp - $requests[$_.Message.Id]).TotalMilliseconds
41+
[PsesLogEntryElapsed]::new($_, $elapsedMilliseconds)
42+
}
43+
44+
$res
45+
}
46+
}

‎tools/PsesLogAnalyzer/Parse-PsesLog.ps1

+26-16
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,11 @@
11

22
$peekBuf = $null
33
$currentLineNum = 1
4-
$logEntryNum = 1
4+
$logEntryIndex = 0
55

66
function Parse-PsesLog {
77
param(
8-
# Specifies a path to one or more PSES EditorServices log files.
8+
# Specifies a path to a PSES EditorServices log file.
99
[Parameter(Mandatory=$true, Position=0)]
1010
[Alias("PSPath")]
1111
[ValidateNotNullOrEmpty()]
@@ -32,6 +32,10 @@ function Parse-PsesLog {
3232
)
3333

3434
begin {
35+
$script:peekBuf = $null
36+
$script:currentLineNum = 1
37+
$script:logEntryIndex = 0
38+
3539
# Example log entry start:
3640
# 2018-11-24 12:26:58.302 [DIAGNOSTIC] tid:28 in 'ReadMessage' C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageReader.cs:114:
3741
$logEntryRegex =
@@ -84,8 +88,8 @@ function Parse-PsesLog {
8488
$line = nextLine
8589
}
8690

87-
if (!$HideProgress -and ($script:logEntryNum % 50 -eq 0)) {
88-
Write-Progress "Processing log entry ${script:logEntryNum} on line: ${script:currentLineNum}"
91+
if (!$HideProgress -and ($script:logEntryIndex % 50 -eq 0)) {
92+
Write-Progress "Processing log entry ${script:logEntryIndex} on line: ${script:currentLineNum}"
8993
}
9094

9195
[string]$timestampStr = $matches["ts"]
@@ -98,17 +102,17 @@ function Parse-PsesLog {
98102

99103
$message = parseMessage $method
100104

101-
[PsesLogEntry]::new($timestamp, $timestampStr, $logLevel, $threadId, $method, $file, $lineNumber,
102-
$message.MessageType, $message.Message)
105+
[PsesLogEntry]::new($script:logEntryIndex, $timestamp, $timestampStr, $logLevel, $threadId, $method,
106+
$file, $lineNumber, $message.MessageType, $message.Message)
103107

104108
if ($DebugTimingInfo) {
105109
$sw.Stop()
106110
if ($sw.ElapsedMilliseconds -gt $DebugTimingThresholdMs) {
107-
Write-Warning "Time to parse log entry ${script:logEntryNum} - $($sw.ElapsedMilliseconds) ms"
111+
Write-Warning "Time to parse log entry ${script:logEntryIndex} - $($sw.ElapsedMilliseconds) ms"
108112
}
109113
}
110114

111-
$script:logEntryNum++
115+
$script:logEntryIndex++
112116
}
113117

114118
function parseMessage([string]$Method) {
@@ -129,29 +133,29 @@ function Parse-PsesLog {
129133
$msg = $matches["msg"]
130134
$id = $matches["id"]
131135
$json = parseJsonMessageBody
132-
$result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json)
136+
$result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize)
133137
}
134138
elseif (($Method -eq 'ReadMessage') -and
135139
($line -match '\s+Received event ''(?<msg>[^'']+)''')) {
136140
$result.MessageType = [PsesMessageType]::Notification
137141
$msg = $matches["msg"]
138142
$json = parseJsonMessageBody
139-
$result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json)
143+
$result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json.Data, $json.DataSize)
140144
}
141145
elseif (($Method -eq 'WriteMessage') -and
142146
($line -match '\s+Writing Response ''(?<msg>[^'']+)'' with id (?<id>\d+)')) {
143147
$result.MessageType = [PsesMessageType]::Response
144148
$msg = $matches["msg"]
145149
$id = $matches["id"]
146150
$json = parseJsonMessageBody
147-
$result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json)
151+
$result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize)
148152
}
149153
elseif (($Method -eq 'WriteMessage') -and
150154
($line -match '\s+Writing event ''(?<msg>[^'']+)''')) {
151155
$result.MessageType = [PsesMessageType]::Notification
152156
$msg = $matches["msg"]
153157
$json = parseJsonMessageBody
154-
$result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json)
158+
$result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json.Data, $json.DataSize)
155159
}
156160
else {
157161
$result.MessageType = [PsesMessageType]::Log
@@ -199,24 +203,30 @@ function Parse-PsesLog {
199203
}
200204

201205
function parseJsonMessageBody() {
206+
$result = [PSCustomObject]@{
207+
Data = $null
208+
DataSize = 0
209+
}
210+
202211
$obj = $null
203212

204213
if ($SkipRpcMessageBody) {
205214
parseMessageBody -Discard
206-
return $null
215+
return $result
207216
}
208217
else {
209-
$result = parseMessageBody
218+
$result.Data = parseMessageBody
219+
$result.DataSize = $result.Data.Length
210220
}
211221

212222
try {
213-
$obj = $result.Trim() | ConvertFrom-Json
223+
$result.Data = $result.Data.Trim() | ConvertFrom-Json
214224
}
215225
catch {
216226
Write-Error "Failed parsing JSON message body with error: $_"
217227
}
218228

219-
$obj
229+
$result
220230
}
221231
}
222232

‎tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml

+115
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,115 @@
1+
<Configuration>
2+
<ViewDefinitions>
3+
<View>
4+
<Name>PsesLogEntry</Name>
5+
<ViewSelectedBy>
6+
<TypeName>PsesLogEntry</TypeName>
7+
</ViewSelectedBy>
8+
<TableControl>
9+
<TableHeaders>
10+
<TableColumnHeader>
11+
<Label>Index</Label>
12+
<Width>6</Width>
13+
<Alignment>right</Alignment>
14+
</TableColumnHeader>
15+
<TableColumnHeader>
16+
<Label>Timestamp</Label>
17+
<Width>24</Width>
18+
<Alignment>left</Alignment>
19+
</TableColumnHeader>
20+
<TableColumnHeader>
21+
<Label>TID</Label>
22+
<Width>5</Width>
23+
<Alignment>right</Alignment>
24+
</TableColumnHeader>
25+
<TableColumnHeader>
26+
<Label>MessageType</Label>
27+
<Width>13</Width>
28+
<Alignment>left</Alignment>
29+
</TableColumnHeader>
30+
<TableColumnHeader>
31+
<Label>Message</Label>
32+
<Alignment>left</Alignment>
33+
</TableColumnHeader>
34+
</TableHeaders>
35+
<TableRowEntries>
36+
<TableRowEntry>
37+
<TableColumnItems>
38+
<TableColumnItem>
39+
<PropertyName>Index</PropertyName>
40+
</TableColumnItem>
41+
<TableColumnItem>
42+
<PropertyName>TimestampStr</PropertyName>
43+
</TableColumnItem>
44+
<TableColumnItem>
45+
<PropertyName>ThreadId</PropertyName>
46+
</TableColumnItem>
47+
<TableColumnItem>
48+
<PropertyName>MessageType</PropertyName>
49+
</TableColumnItem>
50+
<TableColumnItem>
51+
<ScriptBlock>($_.Message -split "`r`n")[0]</ScriptBlock>
52+
</TableColumnItem>
53+
</TableColumnItems>
54+
</TableRowEntry>
55+
</TableRowEntries>
56+
</TableControl>
57+
</View>
58+
59+
<View>
60+
<Name>PsesLogEntryElapsed</Name>
61+
<ViewSelectedBy>
62+
<TypeName>PsesLogEntryElapsed</TypeName>
63+
</ViewSelectedBy>
64+
<TableControl>
65+
<TableHeaders>
66+
<TableColumnHeader>
67+
<Label>Index</Label>
68+
<Width>6</Width>
69+
<Alignment>right</Alignment>
70+
</TableColumnHeader>
71+
<TableColumnHeader>
72+
<Label>Timestamp</Label>
73+
<Width>24</Width>
74+
<Alignment>left</Alignment>
75+
</TableColumnHeader>
76+
<TableColumnHeader>
77+
<Label>TID</Label>
78+
<Width>5</Width>
79+
<Alignment>right</Alignment>
80+
</TableColumnHeader>
81+
<TableColumnHeader>
82+
<Label>Elapsed (mS)</Label>
83+
<Width>13</Width>
84+
<Alignment>right</Alignment>
85+
</TableColumnHeader>
86+
<TableColumnHeader>
87+
<Label>Message</Label>
88+
<Alignment>left</Alignment>
89+
</TableColumnHeader>
90+
</TableHeaders>
91+
<TableRowEntries>
92+
<TableRowEntry>
93+
<TableColumnItems>
94+
<TableColumnItem>
95+
<PropertyName>Index</PropertyName>
96+
</TableColumnItem>
97+
<TableColumnItem>
98+
<PropertyName>TimestampStr</PropertyName>
99+
</TableColumnItem>
100+
<TableColumnItem>
101+
<PropertyName>ThreadId</PropertyName>
102+
</TableColumnItem>
103+
<TableColumnItem>
104+
<ScriptBlock>$_.ElapsedMilliseconds</ScriptBlock>
105+
</TableColumnItem>
106+
<TableColumnItem>
107+
<ScriptBlock>$_.Message</ScriptBlock>
108+
</TableColumnItem>
109+
</TableColumnItems>
110+
</TableRowEntry>
111+
</TableRowEntries>
112+
</TableControl>
113+
</View>
114+
</ViewDefinitions>
115+
</Configuration>

‎tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1

+5-2
Original file line numberDiff line numberDiff line change
@@ -63,13 +63,16 @@ Copyright = '(c) 2017 Microsoft. All rights reserved.'
6363
# TypesToProcess = @()
6464

6565
# Format files (.ps1xml) to be loaded when importing this module
66-
# FormatsToProcess = @()
66+
FormatsToProcess = @('PsesLogAnalyzer.format.ps1xml')
6767

6868
# Modules to import as nested modules of the module specified in RootModule/ModuleToProcess
6969
# NestedModules = @()
7070

7171
# Functions to export from this module, for best performance, do not use wildcards and do not delete the entry, use an empty array if there are no functions to export.
72-
FunctionsToExport = @('Parse-PsesLog')
72+
FunctionsToExport = @(
73+
'Parse-PsesLog',
74+
'Get-PsesRpcMessageResponseTime'
75+
)
7376

7477
# Cmdlets to export from this module, for best performance, do not use wildcards and do not delete the entry, use an empty array if there are no cmdlets to export.
7578
CmdletsToExport = @()

0 commit comments

Comments
 (0)