MSMQ Distributor config best practices

Topics: Logging Application Block
May 22, 2014 at 5:18 PM
Hi,

I have used enterprise library distribution service for logging in our application and write log messages to msmq. MSMQ distributor service reads messages from queue and writes it to log database. When we do load testing for around 100 users, logs are written at a rate of close to 1000 logs per second to msmq. MSMQ Distributor is processing 3-5 messages per second. To speed up the process, I have added another MSMQ Distributor service reading messages from the same queue and write it to database. Still there isn't any performance improvement. Memory usage on both the services shoot up to 4gigs and the process is becoming extremely slow.

I tried different queueTimerInterval values from 150 to 1000 and haven't noticed any performance improvements.

Are there any best practices for msmq distributor service configuration or logging application block for writing logs to message queue?
May 23, 2014 at 5:54 AM
What version of Enterprise Library are you using?

I know that a few users have had startup issues which were helped by setting the generatePublisherEvidence to "false". That doesn't sound like your issue though.

You shouldn't run multiple MSMQ Distributor Services because the service uses Peek to remove messages from the queue so the same message could be processed twice. Also after peeking, Receive is called (to actually remove the message from the queue) which could cause messages to be lost from the queue.

In terms of performance, it would be helpful to profile and see where the time is being spent (e.g. time could be spent on network IO).

Looking at the code there looks to be quite a bit of MessageQueue object creation (although they do get Disposed) -- I'm not sure why one MessageQueue object could not be used (but I'm also not sure what the actual impact of that is).

From a high level the Service does the following while there are items in the queue:
  • Peeks a message
  • Converts from Base64
  • Creates a BinaryFormatter and deserializes to a LogEntry
  • Call EntLib Logger.Write
  • Receive the message from the queue
~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
May 23, 2014 at 5:56 PM
Hi Randy,

Thanks for the quick response. I am using Enterprise Library 5.0. I deleted one service and I am still having performance issues. In my case MSMQ Distributor service is reading messages from a local queue.

What is the preferred "queueTimerInterval" that I should set it in config file. And also can you please tell me how to enable profiling for distributor service.

Regards,
Adi
May 24, 2014 at 8:22 AM
Edited May 24, 2014 at 2:56 PM
To profile the service, you can use Visual Studio or download a profiler (e.g. ANTS, dotTrace, YourKit) and run it against the service.

I'm just curious if you know how many messages were queued (and what size the messages are)? Larger messages could impact performance.

I just ran a test on my laptop. I queued up 600,000 (small) messages, started the service (configured to log to a DB)...then while running queued another 400,000 messages. I did have quite a few (240,000!) MSMQ errors ("Insufficient resources to perform operation.") related to message volume or disk space. Those messages did not get queued. So it took about 20 minutes to to dequeue and log 760,000 messages which is more than 600 entries per second. Memory usage was stable around 10MB.

queueTimerInterval is the interval for the timer to fire. If the queue is full this shouldn't have much impact because as long as there are messages to process the service will keep processing. When the queue is empty then it will sleep for the queueTimerInterval and then wake up to check for messages.

Looking at the source code it is theoretically possible to have a race condition on the flag that determines if the messages should be processed when the timer interval elapses. That would mean that there would be two threads dequeuing at the same time but it seems unlikely to occur and would not explain what you are seeing (it might manifest in duplicate log entries or missing log entries).

If you could get some more information on where the time was being spent it would be helpful. I wonder if it could be related to network IO (but that wouldn't explain the memory usage).

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
May 27, 2014 at 9:31 PM
Hi Randy,

I used dotTrace profiler and below are the user code hot spots.

DistributorService.Main is taking 238,536 ms
PolicyList.Set is taking 65,807 ms
UnityContainer.AddExtension 38,733 ms
NamedTypeBuildKey.GetHashCode is taking 21,517 ms
PolicyList + PolicyKey.SafeGetHashCode is taking 19,132 ms
MsmqLogDistributor.ReceiveQueuedMessages is taking 17,900 ms

and the % time spent is

Wait 47%
System Code 19.10%
Collections 16.42%
User Code 7.56%
Reflection 6.94%
String 1.86%
Linq 0.58%
System.IO 0.38%

I am using a custom trace listener to write one particular category of logs. I guess that might be taking lot of time here. GetLogEntry method of the custom trace listener is taking 99% of UnityContainer.AddExtension method call.

My log messages are ranging from 4,000 to 7000 bytes.

Regards,
Adi
May 28, 2014 at 4:42 AM
I'm a bit puzzled by the numbers. I wouldn't have expected to see the Unity calls taking so much time. Especially I'm surprised to see UnityContainer.AddExtension since I would have thought that any extensions would only be added once.

Can you change the configuration to use another trace listener (I used a DB listener although it filled my hard drive up) to see what the performance difference is? I'm suspecting the custom trace listener -- can you post the code (or share privately if you don't want to post it)? Could the custom trace listener be performing some expensive (or at least relatively expensive) initialization for every LogEntry processed?

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
May 28, 2014 at 10:11 PM
Hi Randy,

Thanks for the help. I was creating a new unity container in custom trace listener class. I removed that line of code and performance is pretty good as you said. Memory usage is constantly around 25KB.

Regards,
Adi
May 29, 2014 at 2:23 AM
Good to hear -- I'm glad you tracked down the issue!

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to