azure-sdk-for-net icon indicating copy to clipboard operation
azure-sdk-for-net copied to clipboard

Utilize formatted message from AzureEventSourceListener in LogEvent

Open christothes opened this issue 1 year ago • 3 comments

closes #44028

@lmolkova - If this fix makes sense, there are other files where we should make this fix.

christothes avatar May 15 '24 14:05 christothes

API change check

API changes are not detected in this pull request.

azure-sdk avatar May 15 '24 15:05 azure-sdk

I think the desire in the original code is to defer formatting the message until/unless it's absolutely needed. In particular, you want to avoid (expensive) formatting if the log level would otherwise filter the event entirely.

I would propose an alternative where we add a second (overloaded) constructor to AzureEventSourceListener that takes a simpler Action<EventWrittenArgs>. Callers that don't need the formatted message can use that constructor.

See this: https://github.com/pharring/azure-sdk-for-net/compare/dev/pharring/EventSourceEventFormattingPerf...pharring:azure-sdk-for-net:dev/pharring/AddAzureEventSourceListenerConstructorOverload?expand=1

pharring avatar May 17 '24 02:05 pharring

I think the desire in the original code is to defer formatting the message until/unless it's absolutely needed. In particular, you want to avoid (expensive) formatting if the log level would otherwise filter the event entirely.

I would propose an alternative where we add a second (overloaded) constructor to AzureEventSourceListener that takes a simpler Action<EventWrittenArgs>. Callers that don't need the formatted message can use that constructor.

See this: https://github.com/pharring/azure-sdk-for-net/compare/dev/pharring/EventSourceEventFormattingPerf...pharring:azure-sdk-for-net:dev/pharring/AddAzureEventSourceListenerConstructorOverload?expand=1

As I read it, the formatting doesn't happen until the event is logged either way. Whether it happens higher or lower in the stack seems immaterial. But perhaps I am missing something?

christothes avatar May 17 '24 14:05 christothes

Yes, you are missing something. In this PR, message formatting (likely a string allocation) still happens unconditionally inside AzureEventSourceListener in order to evaluate the arguments to call the LogEvent callback, passing the fully-evaluated formattedMessage to LogEvent. If the log level is set high/low enough that the event will be filtered, then the fully formatted message is never used -- meaning it was a wasted allocation.

pharring avatar May 20 '24 16:05 pharring

Does the EventSource not avoid the eager formatting when it calls IsEnabled before calling WriteEvent?

christothes avatar May 20 '24 16:05 christothes

Does the EventSource not avoid the eager formatting when it calls IsEnabled before calling WriteEvent?

Yes, it does. However, this listener subscribes to events at "Verbose" level (meaning everything) and the AzureEventSourceListener uses calls EnableEvents without passing a keyword mask -- also meaning "all events".

pharring avatar May 20 '24 17:05 pharring