On the importance of empirical performance testing

Twice recently I thought I had an opportunity to improve performance in my WPF application. Twice I have been wrong and only realized this because I actually tested performance before and after the change.

Example 1:
I have a WPF page with eight combo boxes. I populate the combo boxes from lookup tables in the database. When I initialize the page I populate the combo boxes one at a time. This is fairly common practice.

It occurred to me that as the combo boxes are not dependent on each other I could populate them asynchronously and wait until they had all loaded before continuing. Theoretically this would mean that this section of code would only take as long as the loading of the slowest combo box.

I performed before and after performance tests using a Stopwatch object and found that the single-threaded synchronous code executed in 1.485 seconds on average and the asynchronous code executed in 1.820 seconds on average. In addition, the asynchronous code is less robust because I have to keep track of incomplete asynchronous requests. It became obvious that the original synchronous code was better so I kept it.

Example 2:
I have a requirement to display a datagrid of documents and to display the document number in black if the document has no errors or warnings, blue if it only has warnings, and red if it has any errors. The documents are in a table called GLDocument and the errors are in a linked table called GLDocumentErrors. There is a bit field in GLDocumentError called IsError which is true if the GLDocumentError is an error and false if it is a warning.

My original SQL had three separate subqueries, one to detect each condition.

SELECT D.ID,
  CASE (SELECT COUNT(*) FROM GLDocumentError E WHERE E.GLDocumentID=D.ID) WHEN 0 THEN 0 ELSE 1 END AS HasAnyErrors,
  CASE (SELECT COUNT(*) FROM GLDocumentError E WHERE E.GLDocumentID=D.ID AND IsError=1) WHEN 0 THEN 0 ELSE 1 END AS HasErrors,
  CASE (SELECT COUNT(*) FROM GLDocumentError E WHERE E.GLDocumentID=D.ID AND IsError=0) WHEN 0 THEN 0 ELSE 1 END AS HasWarnings
  FROM GLDocument AS D

It occurred to me that I can get the results I needed with a single subquery which should be a lot faster. By dividing the GLDocumentError row count into the sum of IsError I will get DBNull if there are no GLDocumentError records, 0 if there are only warnings, and > 0 if there are any errors. I just have to cast the IsError from a bit to an float so that I can SUM it and the division result will be a float too. The simplified SQL looks like this...

SELECT D.ID,
  (SELECT SUM(CAST(IsError AS float))/COUNT(*) FROM GLDocumentError E WHERE E.GLDocumentID=D.ID) AS ErrorProportion
  FROM GLDocument AS D

Because this only has one instead of three subqueries it should be a lot faster right? So I SET STATISTICS TIME ON and let rip. Here are the surprising results...

-- For the three subquery SQL
(139160 row(s) affected)
SQL Server Execution Times:
CPU time = 782 ms, elapsed time = 519 ms.

-- For the one subquery SQL
(139160 row(s) affected)
SQL Server Execution Times:
CPU time = 2033 ms, elapsed time = 2755 ms.

 It appears all that CASTing and float division is more expensive than three almost identical subqueries. If you notice, the CPU time of the first query is more than the elapsed time. This tells me the query is being spread across multiple CPUs which accounts for the speed. The second query is probably executing on only one CPU.

So the moral of the tale is that you should always look before you leap!

Working through the dreaded Internal Server Error 500

I just split my huge WCF endpoint into five parts and renamed them. Everything works great in Visual Studio but when I publish to a development server and try the run the application I get the following error when I try to instantiate a connection to the endpoints...

The remote server returned an error: (500) Internal Server Error.
   at System.Net.HttpWebRequest.GetResponse()
   at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)

This is a very generic error, even by Microsoft's standards, which can mean that IIS had a problem starting my service or that an unhandled error occurred in my service.

I started by turning the Failed Request module on in IIS and generating the error again. If you look in Inetpub/logs/FailedReqLogFiles/W3SVC1 you will see many XML files. Open the last one for a very detailed look at the request that failed. The summary of mine looks like this...

As you can see "The operation completed successful" isn't very useful.

Moving on, we try to call the service directly from Internet Explorer from the server itself (not the client machine) with the URL http://it77624/WCFDatabase/Database.svc and we get the following error.

Could not load type 'System.ServiceModel.Activation.HttpModule' from assembly 'System.ServiceModel, Version=3.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089'.

After Googling this error I remembered that I had changed the application names on the WCF Server from DatabaseWCF to WCFDatabase etc. You have to put the  new applications in the 4.0 or 4.5 Classic application pool.

Move the applications for the WCF endpoints into a Classic application pool