ServiceBus EventSource remove allocations and boxing

[danielmarbach]

Similar to #26989 but for ServiceBus to make @JoshLove-msft a happy person too.

Contributing to the Azure SDK

Please see our CONTRIBUTING.md if you are not familiar with contributing to this repository or have questions.

For specific information about pull request etiquette and best practices, see this section.

[ghost]

Thank you for your contribution @danielmarbach! We will review the pull request and get back to you soon.

[jsquire]

/azp run net - servicebus - tests

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[jsquire]

The test LogsTransactionEvents seems to be the source of failures, though it appears to be flaky rather than outright failing. Might be a timing issue or may be something more involved. I haven't had a chance to dig into it at all.

[danielmarbach]

I can also look into it sometime next week. I'm mostly AFK enjoying carnival 🙃

[danielmarbach]

Pushed an update

[danielmarbach]

Is it possible to rerun the tests here to see if things are still flaky?

[jsquire]

/azp run net - servicebus - tests

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[danielmarbach]

Eyeballing it again I think the order of parameters, types as well as the sizes of the parameters should match what we had before. I can explain why it is failing. I pushed now an update the removes the unsafe on one of the Event methods to make sure we have nothing unsafe on the event methods. Other than that I'm a bit clueless what it could be. I need to probably setup the test environment at some point on my machine to get more insights...

[JoshLove-msft]

/azp run net - servicebus - tests

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[jsquire]

Eyeballing it again I think the order of parameters, types as well as the sizes of the parameters should match what we had before. I can explain why it is failing. I pushed now an update the removes the unsafe on one of the Event methods to make sure we have nothing unsafe on the event methods. Other than that I'm a bit clueless what it could be. I need to probably setup the test environment at some point on my machine to get more insights...

Agreed. I've revisited this a couple of times in the last two weeks, and I am at a loss. The results are consistent, though, and show that something in LogsTransactionEvents gets upset. I wonder if this maybe has something to do with TestEventListener rather than the event source itself? Or maybe the Delay used in the test? I haven't been able to dig into those areas yet.

[danielmarbach]

One thing I was thinking too is how the nullable long gets marshalled.
https://github.com/Azure/azure-sdk-for-net/pull/27080/files#diff-a04e2e6a1ccc3dcb86a0a74542e67776cef7660d3fe894c533cd8652c97872d1R353
Long requires 8 bytes but the nullable long 16. I wonder if passing them as part of an array behaves different.

[danielmarbach]

Narrator: It was a bool who made fool not sleep.

[danielmarbach]

This simple repro helped quite a bit

// See https://aka.ms/new-console-template for more information
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;

SomeEventSourceListener listener = new SomeEventSourceListener();

SomeEventSource.Log.TransactionDischarged("TransactionId", " AmqpTransactionId", true);

Console.ReadLine();


sealed class SomeEventSourceListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name.Equals("Some-EventSource"))
        {
            EnableEvents(eventSource, EventLevel.Verbose, EventKeywords.All);
        }
    }

    // from https://blogs.msdn.microsoft.com/dotnet/2018/12/04/announcing-net-core-2-2/
    // Called whenever an event is written.
    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        // Write the contents of the event to the console.
        Console.WriteLine($"ThreadID = {eventData.OSThreadId} ID = {eventData.EventId} Name = {eventData.EventName}");
        for (int i = 0; i < eventData.Payload.Count; i++)
        {
            string payloadString = eventData.Payload[i] != null ? eventData.Payload[i].ToString() : string.Empty;
            Console.WriteLine($"    Name = \"{eventData.PayloadNames[i]}\" Value = \"{payloadString}\"");
        }
        Console.WriteLine("\n");
    }
}

[EventSource(Name = EventSourceName)]
internal class SomeEventSource : EventSource
{
    private const string EventSourceName = "Some-EventSource";

    internal const int TransactionDischargedEvent = 91;

    protected SomeEventSource()
    {
    }

    public static SomeEventSource Log { get; } = new SomeEventSource();

    [Event(TransactionDischargedEvent, Level = EventLevel.Informational, Message = "AmqpTransactionDischarged for LocalTransactionId: {0} AmqpTransactionId: {1} Rollback: {2}.")]
    public void TransactionDischarged(string transactionId, string amqpTransactionId, bool rollback)
    {
        //WriteEvent(TransactionDischargedEvent, transactionId, amqpTransactionId, rollback);
        TransactionDischargedCore(TransactionDischargedEvent, transactionId, amqpTransactionId, rollback);
    }

    [NonEvent]
    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    private unsafe void TransactionDischargedCore(int eventId, string transactionId, string amqpTransactionId, bool rollback)
    {
        fixed (char* transactionIdPtr = transactionId)
        fixed (char* amqpTransactionIdPtr = amqpTransactionId)
        {
            var eventPayload = stackalloc EventData[3];

            eventPayload[0].Size = (transactionId.Length + 1) * sizeof(char);
            eventPayload[0].DataPointer = (IntPtr)transactionIdPtr;

            eventPayload[1].Size = (amqpTransactionId.Length + 1) * sizeof(char);
            eventPayload[1].DataPointer = (IntPtr)amqpTransactionIdPtr;

            var rollbackInt = Convert.ToInt32(rollback);
            eventPayload[2].Size = Unsafe.SizeOf<int>();
            eventPayload[2].DataPointer = (IntPtr) Unsafe.AsPointer(ref rollbackInt);

            WriteEventCore(eventId, 3, eventPayload);
        }
    }
}

[danielmarbach]

This should now pass (famous last words)

[JoshLove-msft]

/azp run net - servicebus - tests

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[jsquire]

/azp run net - servicebus - tests

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[jsquire]

.... and I just realized Josh already ran the tests, so now we get two clean runs. 😄

[danielmarbach]

Ping ;)

[JoshLove-msft]

Ping ;)

Will take a look today - thanks again for your patience @danielmarbach!

[JoshLove-msft]

Thanks @danielmarbach!