Rory Primrose

I've been performance testing a WCF service recently and working away at the bottlenecks in the system. After fixing a few performance issues in the components behind the service endpoint (service implementation and beyond), I was still getting really bad throughput calling the distributed service. The service in this case is hosted on a Windows Server 2003 VM. While it is not on physical hardware, I should be able to achieve better performance than the results I was getting.

After 90 seconds into a load test, the resources on the server got saturated and performance dropped through the floor. After this happened for a minute or so, timeouts and security negotiation failures occurred and test executions essentially halted for the remainder of the load test. I noticed that once service requests were no longer being processed that the server was no longer stressed (CPU dropped back down to normal).

This lead me to think that the reason the host was no longer processing requests was that WCF throttling was occurring. All the test executions passed without timeouts or security negotiation failures once I increased the throttling limits on the host. The test execution time performance still had the same pattern though. The next thought was regarding the binding I was using. The service was configured for wsHttpBinding. This binding has a lot more functionality but also a lot more overhead when compared with basicHttpBinding. To test the theory, I switched the service over to basicHttpBinding.

This is the load test result using wsHttpBinding. The test starts well, then the CPU gets saturated dealing with the wsHttpBinding overhead. The test time starts to bounce around the 8 second mark and the CPU on the server is working way too hard.

Switching over to basicHttpBinding dropped the average test time down to a consistent 28 milliseconds. That is quite an improvement over 8 seconds. This such an increase in performance, I was able to remove the custom throttling configuration and use the default values without a problem.

The CPU on the server is no longer peaking out, but is still working hard because it is processing over 28,000 requests rather than just a few thousand.

This post isn't intended to scare you off using wsHttpBinding. It has its place, but if you don't require its functionality, be aware of the performance implication. You may need to scale up your hardware if you do require wsHttpBinding on a service that will be hit heavily. My preference would be to use netTcpBinding in WAS, but unfortunately Windows Server 2008 is not available to me for this specific scenario.

Tags: Performance, WCF

ReflectorLink 1.0.1 is a minor update to 1.0. It fixes the issue where ReflectorLink wasn't able to resolve the Reflector window in order to ask it to load specific assemblies as determined from the selected context in Visual Studio. The issue was that the title of the window was changed when the application was bought by Red Gate.

You can grab 1.0.1 from the CodePlex project release page here.

Tags: ReflectorLink

There are a few occasions when I have used System.Diagnostics.Trace rather than a System.Diagnostics.TraceSource implementation. Those occasions are limited to scenarios where the consumers of the components didn’t write them, have little interest in their inner workings and don’t need to troubleshoot them. Framework/toolkit type components are the most common implementations that face this.

For example, I have recently done some work on custom tracing implementations that make it really easy for developers to add activity tracing and activity correlation to their code. I wanted to output some messages for diagnostic purposes if there were unexpected issues encountered in the tracing component. Tracing is the right tool for the job, however given that the component is all about tracing, what implementation do I use to trace the information required?

Back to the basic .Net framework is really the only option which means using System.Diagnostics.Trace in this case. This simple reason for this is that in a framework type component, what TraceSource in an application configuration would I use? I’m also not a fan of hard-coded configuration keys if they can be avoided, so Trace seemed like a better option than TraceSource.

In this component, I was tracing three messages regarding an operation that resolves TraceSource implementations. One message indicated a TraceSource name the component was searching for, the second was a warning message if a TraceSource wasn’t found and the third was tracing the result of the resolution. This code is a performance critical code path because it has an incredibly high call rate. If this component isn’t running as fast as possible, whole systems will slow down.

I found this to be the case as I was running load tests against code that used these components.

This is the load test with those three trace messages in the code. This is a particular nasty one. The degrading performance of the test rate (blue line in top left or red line in top right) is not reflective of the increase in user load (red line in the top left). The spike in the CPU also has an interesting behaviour. There is a point where a bottleneck is reached because of the load and the CPU just can’t keep up. The average test time starts peeking out around 36 seconds a test. Without a doubt, this is unacceptable.

If the three trace statements are removed, the difference is dramatic.

The different scales used in the between the two graphs really don’t do this difference the justice it deserves. Without the three Trace statements, the tests sit at a comfortable average of 5.7 milliseconds per test with a maximum of 19 milliseconds. The increase in tests/sec also doesn’t do this change justice. The maximum tests/sec went from 23 to 58. This isn’t however because of a performance bottleneck but quite the opposite. As the performance is now so much better, 58 tests/sec was the maximum number of tests required to execute the test rate defined for 200 users in the load test. This load test could now be cranked up with more tests/user/hr and more users in order to find out what the performance of the code is when running at capacity.

This is a good example of why you should always avoid the Trace class in favour of TraceSource. The Trace class simply writes out to the configured set of TraceListener implementations. There is no SourceSwitch used to indicate whether it should be tracing the type of event being written. It’s implementation also uses a set of foreach statements that are much slower than for statements which, without a preventing SourceSwitch, just slows the code down further.

The TraceSource class is a different beast. Each TraceSource can be configured with a SourceSwitch that defines which trace event types will be written to the configured set of TraceListener implementations. TraceSource is also kinder to your performance because it uses a for statement rather than foreach. This means that even if the SourceSwitch defined will allow the event to be written, it will run through the TraceListeners just that little bit quicker. Such an insignificant improvement in the loop doesn’t sound important, but when the application is invoking that loop operation potentially millions of times, it is really critical.

Tags: Performance, Tracing

I have been writing lots of unit tests for my Toolkit project on CodePlex. The most recent work is adding activity tracing support. As I was writing these unit tests, I came across a bug in the unit testing framework in Visual Studio. If a logical operation is started in the CorrelationManager with a non-serializable object, but not stopped before the unit test exits then the unit test adapter throws an exception.

This is easily reproduced with the following code:

using System.Diagnostics; 
using Microsoft.VisualStudio.TestTools.UnitTesting; 
  
namespace TestProject2 
{ 
    [TestClass] 
    public class UnitTest1 
    { 
        [TestMethod] 
        public void TestMethod1() 
        { 
            Trace.CorrelationManager.StartLogicalOperation(new TestObject()); 
        } 
    } 
  
    internal class TestObject 
    { 
    } 
} 

This fails with the message:

Unit Test Adapter threw exception: Type 'TestProject2.TestObject' in assembly 'TestProject2, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' is not marked as serializable.

It seems that there is an assumption somewhere in the unit test adapter that assumes that the object added to the logical operation stack is the one that the adapter put there (an object that must be serializable). Given that any user code can start its own operation with a custom object, this is a bit of a problem.

The workaround is to ensure that your test stops the logical operation that it started. Internally, this pops the object off the stack. This means that the object on the top of the stack is most likely to be the one that the adapter put there when the unit test adapter goes to serialize/deserialize the object.

For example, the following code passes:

using System.Diagnostics; 
using Microsoft.VisualStudio.TestTools.UnitTesting; 
  
namespace TestProject2 
{ 
    [TestClass] 
    public class UnitTest1 
    { 
        [TestMethod] 
        public void TestMethod1() 
        { 
            Trace.CorrelationManager.StartLogicalOperation(new TestObject()); 
            Trace.CorrelationManager.StopLogicalOperation(); 
        } 
    } 
 
    internal class TestObject 
    { 
    } 
} 

I have raised a bug in Connect here.

Tags: wf, unit testing, Unit Testing, tracing, Tracing

I took my son to a community play group this morning which was the last one of the year. As we arrived, we were told that it was canceled because vandals had torn up the spongy ground material of the playground as well as spray painting the equipment and breaking glass around the place. The cost of vandalism to the community is fairly obvious. When things get damaged, they need to be repaired.

I had never thought about the social cost of vandalism until today. So some people had their few minutes of fun damaging the playground. I don't think they would understand (or care about) the social cost of lots of kids and families that couldn't get together for some play and social time. That is probably up to 30 kids and their families who missed out today. Pity.

Tags:

A couple of years ago I bought a new Dell laptop. It was a middle range spec that I expected to throw more hardware at in the subsequent years. Sure enough, the hard drive became too small, too slow and the machine good certainly do with more than 2Gb RAM.

RAM was the primary concern. It was running out often enough that Vista was constantly going to virtual memory on a slow drive without much space to work with. I ran the analysis tool over at Crucial which to my complete surprise told me that the laptop only supports 2 RAM slots, each of which can only handle a capacity of 1Gb/stick. Surely this was not right. I searched the Dell site and found the specs for the hardware which told the same sad story. Dell in their wisdom sold a Vista laptop that was hardware limited to 2Gb RAM. So I'm not just surprised now, I'm utterly shocked.

Fast forward to this weekend. The machine now takes 20 minutes to work on some task in virtual RAM which leaves the machine completely locked up. After thinking about getting a larger and faster hard drive, I realised that there is a better solution that would be very cheap. Vista came with a technology called ReadyBoost. It uses flash memory to work with virtual RAM before falling back on the hard drive. Flash is faster than hard drives and easily expanable via a USB connection so I get around the hardware RAM restriction. It is also a lot cheaper than buying a new laptop hard drive.

The good guys down at Harris Technology had some ReadyBoost compatible 4Gb USB flash drives for $18 each. I bought one for the laptop and one for the desktop.

After using the laptop a bit yesterday, I found that it was a lot more responsive. When it did use virtual RAM (which happens a lot), the machine was processing a lot faster.

Tags:

I just encountered a curly situation with performance counters. I have added performance counters to a WCF service which has been deployed out to a host platform. When I fire up perfmon.exe on my local machine, the counter category isn't in the list of categories when I specify the remote machine.

All the research on the net seems to point towards a permissions problem. I am an administrator on the server however so this isn't the problem. I can also see other performance categories and counters for that machine, but not the ones I have just installed.

The answer to this one is unexpected. A restart of the Remote Registry service on the server is required. It seems that the remote registry service uses some kind of internal cache of the registry. After restarting that service, the performance counters I'm after are now available to my local machine.

Tags: Performance, WCF

I am working with a bit of code (Manager) that involves caching values based on the type injected as a dependency (Resolver). The same Manager type can be used with different Resolvers and the keys used to store items in the Manager cache that are returned from the different Resolvers should be different.

To achieve this, I generate a cache key that identifies the manager (constant string), the assembly qualified name of the resolver and then the name of the item, TraceSource instances in this case. This means that two resolvers injected into two different managers that are asked to return a TraceSource instance of the same name, will be stored in the managers internal cache as two entries.

When I was unit testing this behaviour, I found that Rhino mock is reusing mocked types. This means that the following code failed:

MockRepository mock = new MockRepository();
ITraceSourceResolver firstResolver = mock.CreateMock<ITraceSourceResolver>();
ITraceSourceResolver secondResolver = mock.CreateMock<ITraceSourceResolver>();

Assert.AreNotEqual(
    firstResolver.GetType().AssemblyQualifiedName,
    secondResolver.GetType().AssemblyQualifiedName,
    "Resolvers have the same name");

The easiest way around this was to get Rhino mock to see the mock definitions as different. The way to do this is request a multi-mock using some interface that means nothing to the test and therefore would have no impact on the test. I chose ICloneable to achieve this.

The following now succeeds and I have two unique mocked types of the same interface to use in my unit tests.

MockRepository mock = new MockRepository();
ITraceSourceResolver firstResolver = mock.CreateMock<ITraceSourceResolver>();
ITraceSourceResolver secondResolver = mock.CreateMultiMock<ITraceSourceResolver>(typeof(ICloneable));

Assert.AreNotEqual(
    firstResolver.GetType().AssemblyQualifiedName,
    secondResolver.GetType().AssemblyQualifiedName,
    "Resolvers have the same name");

Tags: unit testing, dependency injection, rhinomock, Unit Testing

I posted previously about creating EventLog sources without administrative rights. Part of this solution requires that account running the application has rights to create subkeys and write values to the EventLog in the registry. WiX is being used as the installation product so the answer is something like this for the registry key:

<Permission User="[APP_POOL_USER_NAME]" CreateSubkeys="yes" Write="yes"/> 

I found that this didn't work and it failed with the message:

ExecSecureObjects:  Error 0x80070534: failed to get sid for account

The answer to this was that I was not defining the domain for the account. By default, I think it attempts to find the user on the local machine.

Unfortunately it still didn't work. Setting permissions using the alternative element did seem to work successfully.

<util:PermissionEx Domain="[APP_POOL_USER_DOMAIN]" User="[APP_POOL_USER_NAME]" CreateSubkeys="yes" Write="yes" />

Tags: wix, WiX