Skip to content

Commit

Permalink
Revise ETWs so we capture data in columns
Browse files Browse the repository at this point in the history 
By providing method names and args as separate parameters instead of a pre-formatted string, ETW recognizes it as distinct data, allowing us to filter and sort on it, etc.
  • Loading branch information
@AArnott
AArnott committed Aug 17, 2019
1 parent 959bdc7 commit bd10c27
Show file tree
Hide file tree
Showing 2 changed files with 225 additions and 159 deletions.
132 changes: 70 additions & 62 deletions src/StreamJsonRpc/JsonRpc.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1108,18 +1108,13 @@ protected async Task<TResult> InvokeCoreAsync<TResult>(long? id, string targetNa
{
if (!request.IsResponseExpected)
{
if (JsonRpcEventSource.Instance.IsEnabled())
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Verbose, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.SendNotificationStart($"Request Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
JsonRpcEventSource.Instance.SendingNotification(targetName, JsonRpcEventSource.GetArgumentsString(arguments));
}

await this.TransmitAsync(request, cts.Token).ConfigureAwait(false);

if (JsonRpcEventSource.Instance.IsEnabled())
{
JsonRpcEventSource.Instance.SendNotificationStop($"Request Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
}

return default;
}

Expand All @@ -1136,15 +1131,18 @@ protected async Task<TResult> InvokeCoreAsync<TResult>(long? id, string targetNa

try
{
responseDetails = string.Empty;

if (response == null)
{
if (this.TraceSource.Switch.ShouldTrace(TraceEventType.Warning))
{
this.TraceSource.TraceEvent(TraceEventType.Warning, (int)TraceEvents.RequestAbandonedByRemote, "Aborting pending request \"{0}\" because the connection was lost.", id);
}

if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.ReceivedNoResponse(id.Value);
}

if (cancellationToken.IsCancellationRequested)
{
// Consider lost connection to be result of task canceled and set state to canceled.
Expand All @@ -1154,14 +1152,14 @@ protected async Task<TResult> InvokeCoreAsync<TResult>(long? id, string targetNa
{
tcs.TrySetException(new ConnectionLostException());
}

if (JsonRpcEventSource.Instance.IsEnabled())
{
responseDetails = $"Aborting pending request \"{id}\" because the connection was lost.";
}
}
else if (response is JsonRpcError error)
{
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.ReceivedError(id.Value, error.Error.Code);
}

if (error.Error?.Code == JsonRpcErrorCode.RequestCanceled)
{
tcs.TrySetCanceled(cancellationToken.IsCancellationRequested ? cancellationToken : CancellationToken.None);
Expand All @@ -1170,25 +1168,15 @@ protected async Task<TResult> InvokeCoreAsync<TResult>(long? id, string targetNa
{
tcs.TrySetException(CreateExceptionFromRpcError(error, targetName));
}

if (JsonRpcEventSource.Instance.IsEnabled())
{
responseDetails = JsonRpcEventSource.GetErrorDetails(error);
}
}
else if (response is JsonRpcResult result)
{
tcs.TrySetResult(result.GetResult<TResult>());

if (JsonRpcEventSource.Instance.IsEnabled())
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None))
{
responseDetails = $"Success!";
JsonRpcEventSource.Instance.ReceivedResult(id.Value);
}
}

if (JsonRpcEventSource.Instance.IsEnabled())
{
JsonRpcEventSource.Instance.SendRequestStop($"ResponseDetails: {responseDetails}; RequestDetails: Id: \"{request.Id}\", Method: \"{request.Method}\"");
tcs.TrySetResult(result.GetResult<TResult>());
}
}
catch (Exception ex)
Expand All @@ -1205,9 +1193,9 @@ protected async Task<TResult> InvokeCoreAsync<TResult>(long? id, string targetNa

try
{
if (JsonRpcEventSource.Instance.IsEnabled())
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Verbose, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.SendRequestStart($"Request Id: \"{request.Id}\", Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
JsonRpcEventSource.Instance.SendingRequest(id.Value, targetName, JsonRpcEventSource.GetArgumentsString(arguments));
}

await this.TransmitAsync(request, cts.Token).ConfigureAwait(false);
Expand Down Expand Up @@ -1461,6 +1449,7 @@ private async ValueTask<JsonRpcMessage> DispatchIncomingRequestAsync(JsonRpcRequ
Requires.NotNull(request, nameof(request));

CancellationTokenSource localMethodCancellationSource = null;
long idAsLongIfPossible = request.Id is long id ? id : -1;
try
{
TargetMethod targetMethod = null;
Expand Down Expand Up @@ -1547,15 +1536,15 @@ private async ValueTask<JsonRpcMessage> DispatchIncomingRequestAsync(JsonRpcRequ
this.TraceSource.TraceEvent(TraceEventType.Information, (int)TraceEvents.LocalInvocation, "Invoking {0}", targetMethod);
}

if (JsonRpcEventSource.Instance.IsEnabled())
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Verbose, System.Diagnostics.Tracing.EventKeywords.None))
{
if (request.IsResponseExpected)
{
JsonRpcEventSource.Instance.InvokeMethodStart($"TargetMethod = {targetMethod}; RequestDetails: Id = \"{request.Id}\", Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
JsonRpcEventSource.Instance.ReceivedRequest(idAsLongIfPossible, request.Method, JsonRpcEventSource.GetArgumentsString(request.Arguments));
}
else
{
JsonRpcEventSource.Instance.InvokeNotificationStart($"TargetMethod = {targetMethod}; RequestDetails: Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
JsonRpcEventSource.Instance.ReceivedNotification(request.Method, JsonRpcEventSource.GetArgumentsString(request.Arguments));
}
}

Expand All @@ -1574,16 +1563,9 @@ private async ValueTask<JsonRpcMessage> DispatchIncomingRequestAsync(JsonRpcRequ

if (!(result is Task resultingTask))
{
if (JsonRpcEventSource.Instance.IsEnabled())
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None))
{
if (request.IsResponseExpected)
{
JsonRpcEventSource.Instance.InvokeMethodStop($"TargetMethod = {targetMethod}; Result: {result}; RequestDetails: Id = \"{request.Id}\", Method = \"{request.Method}\"");
}
else
{
JsonRpcEventSource.Instance.InvokeNotificationStop($"TargetMethod = {targetMethod}; Result: {result}; RequestDetails: Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
}
JsonRpcEventSource.Instance.SendingResult(idAsLongIfPossible);
}

return new JsonRpcResult
Expand All @@ -1610,7 +1592,14 @@ private async ValueTask<JsonRpcMessage> DispatchIncomingRequestAsync(JsonRpcRequ
}
catch (Exception ex) when (!this.IsFatalException(StripExceptionToInnerException(ex)))
{
return this.CreateError(request, ex);
JsonRpcError error = this.CreateError(request, ex);

if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.SendingError(idAsLongIfPossible, error.Error.Code);
}

return error;
}
finally
{
Expand All @@ -1637,6 +1626,7 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t
throw new ArgumentException(Resources.TaskNotCompleted, nameof(t));
}

JsonRpcMessage result;
if (t.IsFaulted)
{
var exception = StripExceptionToInnerException(t.Exception);
Expand All @@ -1650,12 +1640,11 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t
this.OnJsonRpcDisconnected(e);
}

return this.CreateError(request, t.Exception);
result = this.CreateError(request, t.Exception);
}

if (t.IsCanceled)
else if (t.IsCanceled)
{
return new JsonRpcError
result = new JsonRpcError
{
Id = request.Id,
Error = new JsonRpcError.ErrorDetail
Expand All @@ -1665,23 +1654,31 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t
},
};
}
else
{
result = new JsonRpcResult
{
Id = request.Id,
};
}

if (JsonRpcEventSource.Instance.IsEnabled())
long idIfPossible = request.Id is long id ? id : -1;
if (result is JsonRpcError error)
{
if (request.IsResponseExpected)
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.InvokeMethodStop($"Result: Id = \"{request.Id}\", Method = \"{request.Method}\"");
JsonRpcEventSource.Instance.SendingError(idIfPossible, error.Error.Code);
}
else
}
else
{
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.InvokeNotificationStop($"Result: Method = \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\"");
JsonRpcEventSource.Instance.SendingResult(idIfPossible);
}
}

return new JsonRpcResult
{
Id = request.Id,
};
return result;
}

private JsonRpcMessage HandleInvocationTaskOfTResult(JsonRpcRequest request, Task t)
Expand Down Expand Up @@ -1951,6 +1948,11 @@ private async Task HandleCancellationNotificationAsync(JsonRpcRequest request)
this.TraceSource.TraceEvent(TraceEventType.Information, (int)TraceEvents.ReceivedCancellation, "Cancellation request received for \"{0}\".", id);
}

if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.ReceivedCancellationRequest(id is long v ? v : -1);
}

CancellationTokenSource cts;
lock (this.dispatcherMapLock)
{
Expand Down Expand Up @@ -2011,17 +2013,12 @@ private void CancelPendingOutboundRequest(object state)
},
};

if (JsonRpcEventSource.Instance.IsEnabled())
if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None))
{
JsonRpcEventSource.Instance.CancelRequestStart($"Cancellation request: Id = \"{state}\", Method = \"{cancellationMessage.Method}\"");
JsonRpcEventSource.Instance.SendingCancellationRequest(state is long v ? v : -1);
}

await this.TransmitAsync(cancellationMessage, this.DisconnectedToken).ConfigureAwait(false);

if (JsonRpcEventSource.Instance.IsEnabled())
{
JsonRpcEventSource.Instance.CancelRequestStop($"Cancellation request: Id = \"{state}\", Method = \"{cancellationMessage.Method}\"");
}
}
}).Forget();
}
Expand Down Expand Up @@ -2079,7 +2076,18 @@ private async ValueTask TransmitAsync(JsonRpcMessage message, CancellationToken
try
{
this.TraceMessageSent(message);
bool etwEnabled = JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None);
if (etwEnabled)
{
JsonRpcEventSource.Instance.TransmissionQueued();
}

await this.MessageHandler.WriteAsync(message, cancellationToken).ConfigureAwait(false);

if (etwEnabled)
{
JsonRpcEventSource.Instance.TransmissionCompleted();
}
}
catch (Exception exception)
{
Expand Down
Loading

0 comments on commit bd10c27

Please sign in to comment.