Thursday, July 8, 2010

AppFabric Caching Send Receive Timeout Bug?

Update: apparently this is not a bug. According to Amit Kumar Yadav "these are product internals and not exposed outside. However, I can tell you that this is not a defect.".

I was digging around the AppFabric Caching assemblies using Red Gate’s .NET Reflector today.  I think I may have found a bug in a send/receive timeout that is getting setup in the WCF Transport Channel. The internal class Microsoft.ApplicationServer.Caching.WcfTransportChannel. In method SetupTimeouts, the SendReceiveTimeout is getting set to two times the send timeout value.  I think it should be set to the send timeout + receive timeout. See the attached photo below.  What do you think?

Sunday, July 4, 2010

Performance Comparison Between Reading from Disk vs. Windows Server AppFabric Cache

I just finishing setting up my AppFabric Cache test environment. After reading Scott Hanselman’s blog post about setting up AppFabric Cache, I ran one of the supplied samples CacheVersusDiskPerformance,

This sample shows that it is more efficient to store and read from the AppFabric cache than from disk.

The sample reads a number of image files to simulate user requests to access the files from the disk or from the cache, and compares the time taken to serve the image files.

Could reading from AppFabric Cache be faster than reading from a standard hard disk?  According to some benchmarks by StorageReview, a 5400rpm laptop drive should be able to read anywhere from 24MB/sec to 70MB/sec. If I disregard ethernet overhead, my Intel Pro/1000 network card should be able to push 125MB/sec.  On paper the advantage goes to the network card. 

After opening the DiskVersusCachePerformance solution, compiling a Release build and executing, I saw the following results,

User jerry is logged in
-->SetCurrentAlbum 4
-->View Album/Page 4/0
----->Reading Current Page 0.
----->Albumsize 11 Firstitem 0 Lastitem 10
-------->img1.jpg-DiskRead- error 49406 Delay (ticks) 234915682
-------->img2.jpg-DiskRead- error 31559 Delay (ticks) 153437605
-------->img24.jpg-DiskRead- error 9289 Delay (ticks) 41267264
-------->img24a.jpg-DiskRead- error 49702 Delay (ticks) 216919900
-------->img25.jpg-DiskRead- error 17125 Delay (ticks) 68771122
-------->img26.jpg-DiskRead- error 34290 Delay (ticks) 133337575
-------->img27.jpg-DiskRead- error 15928 Delay (ticks) 71942351
-------->img28.jpg-DiskRead- error 13919 Delay (ticks) 69826076
-------->img29.jpg-DiskRead- error 27446 Delay (ticks) 109123900
-------->img3.jpg-DiskRead- error 64715 Delay (ticks) 296216262
-------->img36.jpg-DiskRead- error 38200 Delay (ticks) 154481239
-->View Next Page Album/Page 4/1
Error : Page limit exceeded Page No.1 PageSize500
Error : ReadPage Fails
-->View Prev Page Album/Page 4/0
----->Reading Current Page 0.
----->Albumsize 11 Firstitem 0 Lastitem 10
-------->img1.jpg-DiskRead- error 49406 Delay (ticks) 236997575
-------->img2.jpg-DiskRead- error 31559 Delay (ticks) 153459270
-------->img24.jpg-DiskRead- error 9289 Delay (ticks) 41270486
-------->img24a.jpg-DiskRead- error 49702 Delay (ticks) 217255944
-------->img25.jpg-DiskRead- error 17125 Delay (ticks) 68804079
-------->img26.jpg-DiskRead- error 34290 Delay (ticks) 133327931
-------->img27.jpg-DiskRead- error 15928 Delay (ticks) 71946776
-------->img28.jpg-DiskRead- error 13919 Delay (ticks) 69829640
-------->img29.jpg-DiskRead- error 27446 Delay (ticks) 108990474
-------->img3.jpg-CacheRead- error 64715 Delay (ticks) 369125
-------->img36.jpg-CacheRead- error 38200 Delay (ticks) 195480
-->View Next Page Album/Page 4/1
Error : Page limit exceeded Page No.1 PageSize500
Error : ReadPage Fails
Logging out jerry Total Delay is 2652685756
Summary of Disk vs Cache
                 Total Average      Average                    Average
                 Files    Size   Disk Delay                Cache Delay
                     # (bytes)        ticks          ms          ticks      ms
Largest File         1 1349351   1395757737   139575.77     1102251300110225.13
Smallest File        1     326    383419933    38341.99        1082331  108.23
Size<50kb          868    1858 245734529.23    24573.45      477272.88   47.73
50kb>Size<500kb     34  148147 323626515.26    32362.65      183153.96   18.32
500kb>Size<2MB      12  892123  719200826.1    71920.08      18372484018372.48
Size>2MB             0       0            0           0              0       0
% Performance using the Cache
Largest File     Access time Cache/Disk %       : 79
Smallest File    Access time Cache/Disk %       : 0
Size<50kb        Access time Cache/Disk %       : 0
50kb>Size<500kb  Access time Cache/Disk %       : 0
500kb>Size<2MB   Access time Cache/Disk %       : 26

What? Disk delay to read a 1.3MB (1,349,351 bytes) file took over almost 140 seconds?!? That is less than 10KB/sec. Unless my disk is about to die, something is wrong. I also noticed a lot of read errors on various image files. How are the files being read and how is the timing done?

I noticed on line 150, the program’s author is using a StreamReader to read the files. As per the MSDN documentation, StreamReader is designed for character input not binary files. Fix up the read of the disk read code,

   1:  Console.Write("-DiskRead-"); source = 0;
   2:  data = File.ReadAllBytes(albumitem.Directory + "\\" + albumitem.Name);
   3:  sizeread += data.Length;
   4:  myCache.Add(key, data, myRegion);

This reduces the disk access by about 50%,

Summary of Disk vs Cache
                 Total Average      Average                    Average
                 Files    Size   Disk Delay                Cache Delay
                     # (bytes)        ticks          ms          ticks      ms
Largest File         1 1349351    692028672    69202.87        1037128  103.71
Smallest File        1     326    217014456    21701.45        1106364  110.64
Size<50kb          868    1858 153729028.18     15372.9      467226.62   46.72
50kb>Size<500kb     34  148147 127915886.34    12791.59      242786.42   24.28
500kb>Size<2MB      12  892123 389407991.33     38940.8      321298.75   32.13
Size>2MB             0       0            0           0              0       0
% Performance using the Cache
Largest File     Access time Cache/Disk %       : 0
Smallest File    Access time Cache/Disk %       : 1
Size<50kb        Access time Cache/Disk %       : 0
50kb>Size<500kb  Access time Cache/Disk %       : 0
500kb>Size<2MB   Access time Cache/Disk %       : 0

but the time is still really slow at 20KB/sec.  A closer look at the source code reveals that the author is performing the standard caching pattern,

  1. Read item from cache
  2. if cache miss
    • read resource
    • cache resource
  3. return resource

The problem the timer is timing the entire operation,

  1. Start timer
  2. Read item from cache
  3. if cache miss
    • read resource (from disk)
    • cache resource
  4. return resource
  5. Stop timer

Since the sample was designed to compare cache vs disk access time, this is clearly wrong. I made some tweaks to the code to measure just what I perceive this example is trying to demonstrate.  Here is the updated block of code,

   1:  // Read the stream of each file
   2:  for (int itemtemp = firstitem; itemtemp <= lastitem; itemtemp++)
   3:  {
   4:      try
   5:      {
   6:          albumitem = albumcontents[itemtemp];
   7:          byte[] data;
   8:          int sizeread = 0;
   9:          string key = albumitem.Directory + "\\" + albumitem.Name;-------->" + albumitem.Name);-DiskRead-"); source = 0;\\" + albumitem.Name);-CacheRead-"); source = 1;^^^^"); done" : (" error " + (albumitem.Length - sizeread)); Delay (ticks) " + elapsedTicks);Error : The file could not be read:");
  10:          Console.Write("
  11:          //
  12:          long elapsedTicks = 0;
  13:          try
  14:          {
  15:              DataCacheItemVersion dumref = null;
  16:              Stopwatch stopwatch1 = Stopwatch.StartNew();
  17:              if ((data = (byte[])myCache.Get(key, out dumref, myRegion)) == null)
  18:              {
  19:                  Console.Write("
  21:                  Stopwatch stopwatch2 = Stopwatch.StartNew();
  22:                  data = File.ReadAllBytes(albumitem.Directory + "
  23:                  stopwatch2.Stop();
  24:                  elapsedTicks = stopwatch2.ElapsedMilliseconds;
  26:                  sizeread += data.Length;
  27:                  myCache.Add(key, data, myRegion);
  28:              }
  29:              else //Get Passed
  30:              {
  31:                  stopwatch1.Stop();
  32:                  elapsedTicks = stopwatch1.ElapsedMilliseconds;
  33:                  sizeread += data.Length;
  34:                  Console.Write("
  35:              }
  36:          }
  37:          catch (DataCacheException ex)
  38:          {
  39:              Console.Write(ex.Message);
  40:              Console.Write("
  41:          }
  43:          string result = (sizeread == albumitem.Length) ? "
  44:          Console.WriteLine(result + "
  45:          delay += elapsedTicks;
  47:          UpdateSummary(albumitem, delay, source);
  48:      }
  49:      catch (Exception e)
  50:      {
  51:          // Let the user know what went wrong.
  52:          Console.WriteLine("
  53:          Console.WriteLine(e.Message);
  54:          continue;
  55:      }
  56:  }

Summary of Disk vs Cache
                 Total Average      Average                    Average
                 Files    Size   Disk Delay                Cache Delay
                     # (bytes)        ticks          ms          ticks      ms
Largest File         1 1349351           23           0            380    0.04
Smallest File        1     326           20           0            319    0.03
Size<50kb          868    1858        11.12           0         168.61    0.02
50kb>Size<500kb     34  148147         8.03           0          89.46    0.01
500kb>Size<2MB      12  892123         11.5           0         113.67    0.01
Size>2MB             0       0            0           0              0       0
% Performance using the Cache
Largest File     Access time Cache/Disk %       : 1652
Smallest File    Access time Cache/Disk %       : 1595
Size<50kb        Access time Cache/Disk %       : 1517
50kb>Size<500kb  Access time Cache/Disk %       : 1113
500kb>Size<2MB   Access time Cache/Disk %       : 988

That looks a little more realistic. Not sure if disk buffer caches are kicking in here. Assuming a low 25MB/sec disk read, a 1.4MB file should take about 50ms to read. That is not what I am seeing here. In this test, we have not measured CPU or network utilization. I would assume the encrypting and signing that AppFabric Caching does by default would add to the over all CPU utilization. Lesson learned? Don’t trust examples, even if supplied by Microsoft. Do your own validation! Please let me know if you see any issues with my observations.

Sunday, March 28, 2010

Using config transforms outside web projects

I saw a tweet from mdulghier yesterday that stated that "unfortunately the msdeploy config transforms don't work with app.configs (just web.configs)." I was initially disappointed, but then thought why is this? So I dug into the reasons behind this.

I found out configuration transforms are not a function of msdeploy, they are a function of msbuild. Although not enabled through VS.NET 2010, you can modify non-web based applications to take advantage of configuration transforms. Below are the manual steps to enable configuration transforms in a console application. Other project types should work as well, but I have not tested it.

12:25pm Update: Added missing instruction regarding ProjectConfigFileName

1. Add a new property ProjectConfigFileName that points to your App.Config file

2. Add a version of App.Config for each configuration, i.e., App.Debug.config To have them nested under App.Config, edit your csproj file,
<None Include="App.Debug.config">

3. Import Microsoft.Web.Publishing.targets into your csproj file right after the Microsoft.CSharp.targets import.
<Import Project="$(MSBuildExtensionsPath)\Microsoft\VisualStudio\v10.0\Web\Microsoft.Web.Publishing.targets" />

4. Call the TransformXml task in your AfterBuild target. Note, the BeforeBuild and AfterBuild targets are commented out by default.
<Target Name="AfterBuild">
    <TransformXml Source="@(AppConfigWithTargetPath)"
                  Destination="@(AppConfigWithTargetPath->'$(OutDir)%(TargetPath)')" />

The complete console application csproj file,
<?xml version="1.0" encoding="utf-8"?>
<Project ToolsVersion="4.0" DefaultTargets="Build" xmlns="">
    <Configuration Condition=" '$(Configuration)' == '' ">Debug</Configuration>
    <Platform Condition=" '$(Platform)' == '' ">x86</Platform>
  <PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Debug|x86' ">
  <PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Release|x86' ">
    <Reference Include="System" />
    <Reference Include="System.Core" />
    <Reference Include="System.Xml.Linq" />
    <Reference Include="System.Data.DataSetExtensions" />
    <Reference Include="Microsoft.CSharp" />
    <Reference Include="System.Data" />
    <Reference Include="System.Xml" />
    <Compile Include="Program.cs" />
    <Compile Include="Properties\AssemblyInfo.cs" />
    <None Include="App.config" />
    <None Include="App.Debug.config">
    <None Include="App.Release.config">
  <Import Project="$(MSBuildToolsPath)\Microsoft.CSharp.targets" />
  <Import Project="$(MSBuildExtensionsPath)\Microsoft\VisualStudio\v10.0\Web\Microsoft.Web.Publishing.targets" />
  <Target Name="AfterBuild">
    <TransformXml Source="@(AppConfigWithTargetPath)"
                  Destination="@(AppConfigWithTargetPath->'$(OutDir)%(TargetPath)')" />

Thursday, March 11, 2010

Retryable actions in C#

Download the Code

2012-10-18 18:00 Edit: I was just informed via Twitter that the source code for this article is no longer available.  I had the source on my SkyDrive.  I will attempt to find it in the next couple of days.  I will post an update with a new link to the source code.  I will most likely post the code to GitHub.

2012-10-18 22:30 Edit: I have uploaded a variation of my retry source code to GitHub. See the download link above.

In inevitably there will be times during the execution of your application where you will encounter an exception. Most common unavoidable types of exceptions are caused when accessing an external resource such as a database or web service. The resource may be known to have occasional expected. A SQL Server Cluster fail-over may only take 5-10 seconds, however, during the fail-over, your application will get a number of different variations of SQLException, varying from connection refused, database not available, etc.

Your database access code may start of with something like the following,

   1:  try
   2:  {
   3:      ReadDatabase();
   4:  }
   5:  catch (SqlException)
   6:  {
   7:      // return error to user?
   8:  }

Your first thought may be to catch the known exception type and try the action again, such as,

   1:  try
   2:  {
   3:      ReadDatabase();
   4:  }
   5:  catch (SqlException)
   6:  {
   7:      try
   8:      {
   9:          ReadDatabase();
  10:      }
  11:      catch (SqlException)
  12:      {
  13:          // failed again, return error to user?
  14:      }
  15:  }

If there is only one place in your code you have to do this, then this approach may be acceptable. However, more likely there will be a fair number of places you need to catch an exception and try again. In each of these places, the conditions and behavior will not be the same. You will want to handle retrying of certain blocks of code in a consistent manner. Enter Retryable....

Introducing Retryable

Retryable is a class that allows a consistent and extensible way to automatically retry code that is commonly subject to exceptions. Before showing some code, there are are few things you should keep in mind before blindly wrapping your error prone code with retry functionality.

The first is side effects. Will the retry cause unexpected delays or program hangs? Retry waits should be kept to an minimum. Second, with automatic retrying code there are two design decisions to consider
  • In what case do you want to retry the action.
  • How much time should elapse between attempts

The Retryable class has a number of overloads of the Execute method. The simplest is

public static void Execute(Action action);

This method can be called in any of the following ways,

// using anonymous method
Retryable.Execute(delegate() { ReadDatabase(); });
// using lambda
Retryable.Execute(() => ReadDatabase());
// using method group...

But wait! What about those design decisions? How many times and in what conditions does the it retry? How long does wait between attempts? Before answer this, I must first introduce couple of other components.


IRethrowEvaluator is an interface that is called when an exception is thrown by the Action target. It has a single method named Rethrow,

   1:  public interface IRethrowEvaluator
   2:  {
   3:      bool Rethrow(int retryCount, Exception exception);
   4:  }

If the Rethrow method returns true, the exception will be rethrown, otherwise the Action target will be retried. Implementations can examine the retryCount and exception parameters to determine if it is an appropriate reason to retry. If your code expects database connection issues or deadlock to manifest as a SQLException, you should only retry if the SQLException represents a connection problem or deadlock. If the SQLException represents an invalid query or permission problem, it does not make sense to retry. You need to be clear on what conditions you are trying to recover from.


ISleepEvaluator is an interface that is called if the IRethrowEvaluator return false. The ISleepEvaluator interface is very similar to IRethrowEvaluator,

   1:  public interface ISleepEvaluator
   2:  {
   3:      int SleepMilliseconds(int retryCount, Exception exception);
   4:  }

It should be pretty clear what this method is supposed to do. It gets the same parameters as IRethrowEvaluator. It returns the number of milliseconds to sleep before the next call to action is attempted. You can adjust the amount of time to wait based on how many items the action has been retried and what caused it to fail the last time.

Putting it all together

The examples above did not pass instances of either of these interfaces. There a number of overloads to the Execute method,

public static void Execute(Action action, IRethrowEvaluator rethrowEvaluator, ISleepEvaluator sleepEvaluator)

If IRethrowEvaluator is not specified, the default implementation will retry 5 times, i.e., retryCount == 4, on any type of Exception.

If ISleepEvaluator is not specified, the default implementation will use a random exponential delay with minimum of 5ms. I discovered this technique on JD Conley's blog post Functional Optimistic Concurrency in C#. The implementation is pretty elegant,

   1:  private static int SleepMilliseconds(int retryCount, int minimumDelay)
   2:  {
   3:      Random random = new Random(Guid.NewGuid().GetHashCode());
   4:      return random.Next((int)Math.Pow(retryCount, 2) + minimumDelay,
               (int)Math.Pow(retryCount + 1, 2) + 1 + minimumDelay);
   5:  }

You can implement IRethrowEvaluator and ISleepEvaluator as simple or as complex as you require. However, most of the time, you may want very simple conditions and waits. To assist in these common situations, you can use the helper static classes, ThrowIf and SleepFor,

   1:  Retryable.Execute(
   2:      ReadDatabase,
   3:      ThrowIf.RetryCountIs(9),
   4:      SleepFor.Milliseconds(250));
   6:  Retryable.Execute(
   7:      ReadDatabase,
   8:      ThrowIf.RetryCountIs(9),
   9:      SleepFor.RandomExponential(250));
  11:  Retryable.Execute(
  12:      ReadDatabase,
  13:      ThrowIf.Custom((retryCount, exception) => retryCount == 9 && exception.GetType() == typeof(SqlException)),
  14:      SleepFor.Custom((retryCount, exception) => (retryCount + 1) * 100));

The Retryable class has a number of overloads taking Action, Action<T>, Action<T1, T2>, etc and Func<TResult>, Func<T, TResult>, giving the user many options. Note that not all possible combinations have been implemented. I have only implemented it overloads that I required.

I have found this set of classes very useful in situations where occasional expected exceptions are expected but can be recovered from retrying the action. Consumers of these classes have ability to control what should happen when an exception is raised and evaluate if the action should be retried and now long to wait between attempts.

Your thoughts?

Friday, August 14, 2009

Upgrading Vista x64 Business to Windows 7 x64 Enterprise

Tonight I decided to take a little risk and upgrade my physical work PC from Windows Vista Business x64 to Windows 7 Enterprise x64. I say it is only a little risk since I did a practice run upgrading an install of Vista Business x86 to Windows 7 x86 Ultimate inside VMware. Since my work PC was a member of a domain, I decided to try the in-place upgrade. I really hope I do not have to re-add the computer to the domain after wards. A couple of blog posts I read indicated to allow for four hours for this kind of upgrade. Four hours! Since I am a consultant, I can not really bill this many hours to a upgrade that is not required (or even on the radar). I thought Friday night would a good opportunity. Heck, if anything goes wrong, I have the entire weekend to get my PC working again before Monday.

To help minimize the upgrade time, I ensured I uninstalled any non-core applications. The thinking here is more installed programs, the more time it will take to migrate. The upgrade advisor warned me about the following items,

Upgrading Windows will affect the following devices and/or programs:

      These programs might not work properly after the upgrade. We recommend uninstalling these programs before upgrading. Cancel the upgrade, open Control Panel, and search for "uninstall a program". (Note: Programs marked as * can be safely reinstalled after the upgrade.)
    • VMware Player *
    • ATI CATALYST Install Manager *
    • ATI Catalyst Control Center *

    I do not use the VMware Player part of VMware workstation and the ATI drivers can easily reinstalled later. When I ran the manual upgrade adviser it had also warned me about the Intel Management Engine Interface, however it was not warning me now. I will just move forward with the upgrade, crossing my fingers, hoping for the best.

    Our PC's are HP Compaq dc7900 Small Form Factor PC with Intel Core 2 Quad Q9400 processor, 16GB RAM (we run a VM or two or three...) and 160GB of RAID 1 storage.

    I started by logging into my workstation with an Administrator account. I popped in the Windows 7 Enterprise x64 DVD and ran setup. From start to finish the total elapsed time was 1 hour, 20 minutes. Once I was past the initial few questions, the rest of the installation did not require any user interaction. Below are steps the installation took and the approximate time to complete that step.

    24Prepare, Copy, reboot to "Upgrading Windows"
    6Gather Information before expanding files
    10Expand 2,792MB of installation files
    2Install Features and Updates
    1Update Registry
    3Starting step "Transfer Files, settings and programs"
    13Transfer Files X of Y (mine had 559,513 total)
    11Transfer Files X of Y, restarted at 63% complete.
    3Setup checking computer for first use

    At this point I was able to enter Ctrl-Alt-Delete to log on. Much to my surprise, my computer was still a member of the domain and almost all my programs were working as before.

    I was surprised when I fired up VMware Workstation and it could not connect to the build server. A quick check of the host's network adapters, shows no VMware Network Adapters. A web search did not turn up anything interesting, so a quick reinstall of VMware Workstation resolved the problem.

    The other product I was concern about is the organization's virus scanner software. One of the domain administrators had mentioned to be careful about the Trend Micro OfficeScan software. My workstation is running Trend Micro OfficeScan Client for Windows 64-bit edition, version 8.0 Service Pack 1. Luckily, it appears to be working without issue.

    I was required to re-Activate Windows. Although I did not think it would work, I tried to Activate Windows without entering the new product key. It failed. I went to the properties of My
    Computer, and used the Change product key functionality. I entered my Windows 7 Enterprise x64 product key and activated successfully.

    Overall, I am very impressed with the upgrade process. Knowing what I know now, I would be comfortable uninstalling the incompatible products and running the upgrade while I attend an hour or two meeting. When I get back to my desk, I would be able to log on to Windows 7 for the first time, re-install VMware and be back to productive work without any significant impact. Good work Microsoft!

    Saturday, September 20, 2008

    Step-By-Step Guide for AD FS - Errata Comments

    Michèle Leroux Bustamante (aka that Indigo Girl) has a good post on setting up Active Directory Federation Services. She points out a few gotchas when trying to follow the Tech Net lab "Step-By-Step Guide for AD FS" in Windows Server 2008.

    Step-By-Step Guide for AD FS - Errata Comments

    Hopefully this will save you a bit of time.

    Monday, September 1, 2008

    Generic Secure Token Service with Sample

    I have updated my Generic Secure Token Service with a sample. The generic STS sample is entirely setup using the web.config file. No global.asax or default.aspx pages. The relying party web site has a sample anonymous page to demo how to allow users anonymous access to certain pages.

    Next time, I plan on having a federated passive sts sample completed.

    Download the source code.