Correlation and Logging

Sep 9, 2013 at 12:07 PM
Hi,

The logging infrastructure that Microsoft.Owin package is providing is really great. However, I don't see that ActivityId is set for trace messages. I'm not sure if I am at the right path here but based on my current knowledge, this can be done by setting the Trace.CorrelationManager.ActivityId. This's a static property and I cannot see what would happen if I try to set it manually as I can be getting multiple request at the same time (in other words, in a multi-threaded environment).

What is the suggested way to enable this type of behavior?
Coordinator
Sep 9, 2013 at 4:03 PM
Katana's logging infrastructure does not currently have any support for correlation. The logging infrastructure is not designed for verbose per-request logging, it would be far too slow. It is primarily designed to report error conditions. What kind of information are you trying to log?
Sep 10, 2013 at 7:05 AM
I was trying to hook up the ASP.NET Web API's tracing into Katana's. I thought it won't be a big perf issue as we can filter the level of information. So, I would only enable for Warning, Critical and Error to be logged in prod and have everything to be logged in dev.

does this make sense?
Coordinator
Sep 10, 2013 at 4:16 PM
Ah. I'm not very familiar with WebApi's tracing infrastructure, but it should be possible to wire that up over top of Katana.
Sep 10, 2013 at 5:09 PM
Coordinator
Sep 10, 2013 at 7:40 PM
Not with the existing infrastructure. Open a bug please.
Sep 11, 2013 at 7:16 AM
Mar 5, 2014 at 3:10 PM
The logging infrastructure is not designed for verbose per-request logging, it would be far too slow. It is primarily designed to report error conditions.
Is this still the case? If so, is this because of the TraceSource or something to do with how the way Katana uses it?

We are considering using katana's logging infrastructure in Windows Azure as it hooks up with azure's diagnostic agent very well but this statement that Chris has made is always bugging me :s

any in-depth knowledge would be much appreciated.

Thanks in advance,

Tugberk
Coordinator
Mar 5, 2014 at 4:10 PM
It depends on your trace listener. When you use a text file trace listener every log statement incurs significant IO costs. If you're logging anything more than rare error conditions then you will slow down the whole application.

I'm not sure how Azure's infrastructure hooks in.

ETW is designed for high throughput scenarios.
Mar 5, 2014 at 5:49 PM
Edited Mar 5, 2014 at 10:31 PM
IMHO, the tracing cost is a non-issue as it is basically a pay-to-play scenario: of course it will slow down your application when it is enabled (in particular with a high-verbosity level or with non thread-safe listeners that require locking like TextWriterTraceListener or XmlWriterTraceListener), but it won't cost you much when disabled (just the cost of a bitwise operation in SourceSwitch.ShouldTrace).

I've personally looked at ETW these last weeks and concluded that its high-throughput is not enough to forget its terrible complexity and the lack of good tooling: neither xperf, WPR or even the promising SvcPerf can (yet) compare with the amazing Service Trace Viewer + XmlWriterTraceListener duo. I've personally never found a better way to trace your whole application across processes, machines or even entire networks. What you can do with this tool is just amazing when your application uses System.Diagnostics correctly.

As of today, OWIN - like Web API btw - comes with a limited tracing support that would make any WCF dev laugh: requests are not traced, event IDs and correlation are never used and the trace sources aren't that numerous.

That would be amazing to see such a support in OWIN. That said, I imagine it won't come painlessly (I see at least a blocking issue: in a ASP.NET host, the AspNetSynchronizationContext always overrides the Trace.CorrelationManager.ActivityId value with the HTTP.SYS correlation ID after each async call which ruins every activity tracing you'd insert in your code.).

EDIT: an image is probably better than a long and vain explanation. This is what a few TraceEventType.Transfer events and the Service Trace Viewer allow you to do:

Image