Can't see FormattedMessage for EventSource events in PerfView

[noahfalk]

Opening new issue on behalf of @joacar. It wasn't clear if the original issue #26727 was related. Copied from #26727 (comment)

Hi,

I'm trying to create counters dynamically and it works all though I'm not sure it's the recommended approach. The upper limit of http clients (see zip) is bounded by 50.

The gist of my solution:

1. Create DiagnosticListener and listen to System.Net.Http.RequestOut.Start and Stop
2. A static instance of EventSource that has a ConcurrentDictionary to keep a metric for each http client making a request on RequestStart and RequestStop.

I loaded the .trace file into perfiew and can't see the formatted message nor is the method name appended to the event name, as seen here (source). Read some article on MSDN that the number of arguments sent to method should be sent in the same order to WriteEvent for it to work. Thing is, I don't use raw EventCounter instead I rely on PollingCounter et al.

Thanks

WebApplication1.zip

[noahfalk]

can't see the formatted message nor is the method name appended to the event name

What command are you using to collect the trace and which events are you expecting to see this information for? I assumed the picture you linked is to show an example of behavior you were expecting (it does have text in the FormattedText column), let me know if that isn't the correct interpretation.

When I looked at your repro I saw a few potential issues:

1. The implementation of event logging functions (such as ModuleRequestStarted) in the ModuleEventSource never calls WriteEvent(…) so no event is logged.

2. The comments suggested running dotnet-trace using command-line:

// dotnet trace collect -p <pid> --providers My.Custom.Source.WebApplication1

If you want the trace to collect the counters (and you don't have to) then you need to tell it how often to collect them. It can be indicated like this:

dotnet-trace collect -p <pid> --providers My.Custom.Source.WebApplication1:::EventCounterIntervalSec=1

[noahfalk]

Read some article on MSDN that the number of arguments sent to method should be sent in the same order to WriteEvent for it to work

If your goal is only to log counters and not to log the explicit events for each RequestStart and request failure then you probably want to remove the [Event(...)] attribute from those methods and use the NonEvent attribute instead. If your goal is to log an event each time a request starts/fails then you should call WriteEvent(...) inside the implementation of ModuleRequestStarted and ModuleRequestFailed.

As the code is currently written you won't get explicit events for RequestStart/RequestFailed because WriteEvent() is never called. The Event attribute causes no harm that I am aware of, but it might confuse someone reading the source. There are also some minor side-effects where EventSource is creating data structures/event manifests assuming that RequestStart/RequestFailed events might be emitted but they never are.

[joacar]

Thanks @noahfalk for clarification and educating me. I assumed that writing an event counter also wrote corresponding event. I've updated the code to call WriteEvent but FormattedMessage is still blank.

[Event(Id.RequestCompletedId, Message = "Request for module '{0}' completed", Level = EventLevel.Informational)]
public void RequestCompleted(string moduleId)
{
    WriteEvent(Id.RequestCompletedId, moduleId);
    // ...
}

Thanks for the tip about fetching interval counters with specified interval. That explains why I occasionally saw them in perfview.

I'm thinking of writing an event with a formatted message HTTP/{Version} {Method} {Uri.Authority} responded {StatusCode} in {ElapsedTime} ms. Since I'm using HttpClientFactory parts of this information is already logged (see below) and maybe it's already an event doing what I'm planning. Is there any built in event that tracks outgoing HTTP calls in this fashion?

info: System.Net.Http.HttpClient.<Name>.LogicalHandler[100]
      Start processing HTTP request GET http://localhost:63697/test
info: System.Net.Http.HttpClient.<Name>.ClientHandler[100]
      Sending HTTP request GET http://localhost:63697/test
info: System.Net.Http.HttpClient.<Name>.ClientHandler[101]
      Received HTTP response after 86203.4755ms - OK
info: System.Net.Http.HttpClient.<Name>.LogicalHandler[101]
      End processing HTTP request after 86213.6493ms - OK

[noahfalk]

but FormattedMessage is still blank.

I investigated a bit and there are appears to be more than one issue causing this. The first one that I expected is that you are running into a current limitation with nettrace file serialization. When collecting using ETW (.etl files) the string you put in the Message attribute is transmitted as part of the trace, but the nettrace file isn't saving it. Without the template string available PerfView is unable to produce the final formatted string. This is one of the unfortunate rough edges where nettrace isn't yet at full parity with ETW capabilities.
However then I went to test this using an ETW collection (Collect menu -> Collect menu item -> Write "*My.Custom.Source.WebApplication1:::EventCounterIntervalSec=1" in the additional providers text box) and it still didn't work. I was seeing that the majority of events in the trace didn't have FormattedMessage, not just the ones produced by the custom EventSource. I haven't tracked down a root cause, but it suggests there is at least one additional bug preventing this from working properly.

As a workaround if you get rid of the FormattedMessage column in PerfView then the Rest column will show you the raw key/value pairs that were collected, including your moduleId parameter:

Is there any built in event that tracks outgoing HTTP calls in this fashion?

HttpClient supports pluggable handlers that can run code when the message is going out or a response is coming back. The logging you've spotted comes from two different handlers that I was aware of, though you could also add your own:

1. The DiagnosticSource logging the current code hooks into comes from the DiagnosticsHandler which is included in all HttpClient instances by default.
2. The ILogger based logging you noticed comes from the LoggingHttpMessageHandler which is injected by the implementation of IHttpClientFactory you are using.

Unless you want to add your own HttpMessageHandler to log in a custom way, the rest of the solutions are around converting between the forms of logging that are in place and the form of logging you ultimately want. If your goal is to get the logging out-of-process using dotnet trace then we are looking at solutions that convert from DiagnosticSource -> EventSource or from ILogger to EventSource. You already spotted the option to implement your own DiagnosticListener and do the conversion directly. Likewise you could create your own ILoggerProvider and do a similar conversion on the ILogger messages. However there are also two existing mechanisms that might give you what you were hoping for:

1. DiagnosticSourceEventSource - This is a built in EventSource that can configured to capture and convert arbitrary DiagnosticSource events into EventSource events. Although not as flexible as doing a custom listener, it has the advantage that it ships in the runtime making it available for all .Net Core apps. The configuration is also done externally using filter arguments (the same way we configured the polling interval for the counters) which means any .Net Core app can be traced this way without doing any special configuration inside the app's code.
2. EventSourceLoggerProvider - This converts ILogger messages into EventSource events and from 3.0 onwards it is enabled as a default provider in asp.net core apps. Similar to the DiagnosticSourceEventSource it can capture arbitrary ILogger messages and it can be configured externally using filter arguments.

Sorry about the FormattedMessage troubles but hope this info helps : )

[joacar]

Great post! I‘ve read it and intend to look into it in more detail and provide an answer to your proposals. I’ll mention another potential finding (so I won’t forget it my self) and it relates to ‘in’ parameter modifier passed to a method that in turns calls ‘WriteEvent’ with that parameter fails. I’ll provide a repro when I have the opportunity.

Thanks again for a great answer, really appreciate it and the great work put into .NET Core