Rhino Queues perf

[Ayende Rahien]

Hi guys,
I am doing some perf testing for RQ.
I managed to improve perf by about 40%, which is good, but currently I am focusing on this scenario:

private static void AddData(IQueueManager manager, byte[] bytes)
{
    var sp = Stopwatch.StartNew();

    for (int i = 0; i < 10000; i++)
    {

        using (var tx = new TransactionScope())
        {
            manager.Send(new Uri("rhino.queues://localhost:2222/test1"), new MessagePayload
        {
            Data = bytes
        });


            if (i % 10 == 0)
                Console.WriteLine(i);

            tx.Complete();
        }
    }

    Console.WriteLine("{0:#,#}", sp.ElapsedMilliseconds);
}


This takes about 2.7 minutes to run right now.
Profiling this shows over 40% of the time spent in system.transaction.transaction.dispose.

I am not sure how to approach fixing this.
Any ideas?

[Corey Kaylor]

I believe the Dispose call  for TransactionScope is blocking until the send is complete.

[Corey Kaylor]

We ran into this in a different project, even the msdn documentation that suggests how to deal with multi-threaded transactions by creating a clone doesn't work because of the Dispose still blocks. The only way we successfully dealt with this in the past was using a CommitableTransaction and commiting / disposing at the proper times. I would gladly like to hear of another possibility though.

[Ayende Rahien]

No, it most definitely should not. That is done on another thread, and is completely async from the send op.

[Ayende Rahien]

Not sure that I am following you here.

[Corey Kaylor]

Is the same transaction being used for the queued send and the actual send until a confirmation is given of receipt?

[Corey Kaylor]

Straight from the MSDN documentation on Dispose for TransactionScope "This method is synchronous and blocks until the transaction has been committed or aborted." So if the same transaction DTC or otherwise is used for both the persisted queued send and the actual send it will block until the send is complete and committed. So my comment above was under the assumption that it is the same transaction. If it's not, then what I've described is not true.

[Ayende Rahien]

Nope.
The TX is only to save things to storage.

[Ayende Rahien]

No, that is not it.
And I did a second check. 75%(!) of the time goes to Disppose.
The problem is that I am not following why it is taking so long to manage a single enlistment.

[Ayende Rahien]

DAMN!
I implemented ISinglePhaseNotification - same code now run in 17 seconds!

[Corey Kaylor]

That's impressive! Glad you were able to track it down.

[Ayende Rahien]

No, just a single scenario.

private static void CopyData(IQueueManager manager)
{
    Console.WriteLine("starting copy");
    Stopwatch sp = Stopwatch.StartNew();

    for (int i = 0; i < 10000; i++)
    {
        using (var tx = new TransactionScope())
        {

            var message = manager.Receive("test1");
            manager.Send(new Uri("rhino.queues://localhost/test2"), new MessagePayload
            {
                Data = message.Data,
                Headers = message.Headers

            });

            if (i % 10 == 0)
                Console.WriteLine(i);
            tx.Complete();
        }
    }

    Console.WriteLine("{0:#,#}", sp.ElapsedMilliseconds);
}

This takes 5.7 minutes for 10,000 msgs.

[Corey Kaylor]

OK, maybe not so impressive...

[Ayende Rahien]

STUPID of me
I wasn't clearing the queue of the old messages.
This now perform 10,000 messages in 90 seconds!
I think that this is acceptable for now.

[Steve Wagner]

Now where you work on Rhino Queues i want to remind you on this issue :-)

------------------------------

Ive created two simple command line applications to test how RSB works.
App 1 sends a simply message to app 2, so not complicated. The reason
for that mail is what app 2, which received the messages, outputs at
startup when i restart the application after all messages where handled.

RSB: Scanning incoming message
95514ec0-36af-42ba-9951-9ada5a105202/3a54c5f7-54c7-4966-a99e-9c73009293c0
on 'test2/' with status Processing
RSB: Scanning incoming message
95514ec0-36af-42ba-9951-9ada5a105202/ea075fcb-0082-4cd1-a648-9c73009293cc
on 'test2/' with status Processing
RSB: Scanning incoming message
95514ec0-36af-42ba-9951-9ada5a105202/d83a92df-e153-497c-a1d2-9c73009293d3
on 'test2/' with status Processing
...

All messages are processed and ComsumerOf are called before i restarted
the app, so why the message status is still Processing?

-----------------------------

-Steve

Ayende Rahien schrieb:

[Ayende Rahien]

Yes, this is fixed.

[Ayende Rahien]

That was the big perf boost

[Steve Wagner]

:-) Than you could mark the issue as fix which ive submitted to GitHub RSB.

Ayende Rahien schrieb: