UrlRewritingNet performance issues

My organization has recently spent hundreds of total man-hours troubleshooting production CPU/performance issues that we have identified as being caused by the third party UrlRewritingNet.UrlRewrite module. This post will be a summary and debrief of our troubleshooting and resolution. If you are using this component and are experiencing performance issues, perhaps this will be beneficial to you.

Background and disclaimer

First, the disclaimer: I can not conclusively prove that there is anything wrong with UrlRewritingNet. I’ve only briefly reviewed the source code and confirmed it’s not blatantly terrible. For all intents and purposes it seems like a fine, albeit older (and what appears to be no longer maintained) free URL rewriting solution for ASP.NET applications.

UrlRewritingNet is implemented as an HTTPModule. Rewrite rules are defined as a regular expression in a configuration file (or in the web.config). On every request, they are evaluated and the module “rewrites” the URL as necessary. It can also be interfaced with programmatically.

<add name="rule1" virtualUrl="^~/test/(.*).aspx" destinationUrl="~/test.aspx?q=$1" />

As for the background, my company’s website was using this to rewrite URLs for some sections of the site. We had about 100 rules, which I don’t consider to be exceptional. For a long time, our production web servers were having intermittent performance issues (specifically high CPU utilization related to the W3WP.exe process). Inevitably this issue would subside just long enough for us to ignore it, until it came back with even higher or prolonged instances of excessive CPU utilization. Eventually, it became too much to ignore, and we finally identified and resolved the problem.

Debugging Tools for Windows

This was the classic “it works on my machine” problem that is so hard to diagnose. There were no exceptions, no problems on any non-production machine, no database server issues. All we knew was that the production web servers (Server 2003/IIS6 by the way) were intermittently collapsing under the pressure of…something.

What saved us was a memory dump – a few of them, actually. We installed the Debug Diagnostic Tool on one of the production servers and performed a full IIS hang dump. We then loaded up the dump file in WinDbg, wired up SOS and got to work.

0:000> !threads

This command shows information about the managed threads. There happens to be 22 threads, all background. Nothing particularly unusual here. Moving on.

0:000> !eestack

This command dumps all thread stacks. Below is one of the threads. Note the bold. (this has been edited a bit for brevity)

… 
mscorlib_ni!System.RuntimeType+RuntimeTypeCache+MemberInfoCache`1[[System.__Canon, mscorlib]].Insert...
mscorlib_ni!System.RuntimeType+RuntimeTypeCache+MemberInfoCache`1[[System.__Canon, mscorlib]].AddMethod...
mscorlib_ni!System.RuntimeType.GetMethodBase(System.RuntimeTypeHandle, System.RuntimeMethodHandle)+0x1a0
mscorlib_ni!System.Reflection.Emit.DynamicScope.GetTokenFor(System.RuntimeMethodHandle)+0x30
mscorlib_ni!System.Reflection.Emit.DynamicILGenerator.Emit(System.Reflection.Emit.OpCode, System.Reflection.MethodInfo)+0x149
System_ni!System.Text.RegularExpressions.RegexCompiler.Callvirt(System.Reflection.MethodInfo)+0xa5
System_ni!System.Text.RegularExpressions.RegexCompiler.GenerateOneCode()+0x11b0
System_ni!System.Text.RegularExpressions.RegexCompiler.GenerateForwardSection()+0x1529
System_ni!System.Text.RegularExpressions.RegexCompiler.GenerateGo()+0x13b
System_ni!System.Text.RegularExpressions.RegexLWCGCompiler.FactoryInstanceFromCode(System.Text.RegularExpressions.RegexCode, ...
System_ni!System.Text.RegularExpressions.RegexCompiler.Compile(System.Text.RegularExpressions.RegexCode, System.Text.RegularExpressions.RegexOptions...
System_ni!System.Text.RegularExpressions.Regex.Compile(System.Text.RegularExpressions.RegexCode, System.Text.RegularExpressions.RegexOptions)+0x12
System_ni!System.Text.RegularExpressions.Regex..ctor(System.String, System.Text.RegularExpressions.RegexOptions, Boolean)+0x202
UrlRewritingNet_UrlRewriter!UrlRewritingNet.Web.RegExRewriteRule.CreateRegEx()+0x62
UrlRewritingNet_UrlRewriter!UrlRewritingNet.Web.RegExRewriteRule.Initialize(UrlRewritingNet.Configuration.RewriteSettings)+0x74
UrlRewritingNet_UrlRewriter!UrlRewritingNet.Web.UrlRewriteModule.Init(System.Web.HttpApplication)+0x1a1
System_Web_ni!System.Web.HttpApplication.InitModulesCommon()+0x7c
System_Web_ni!System.Web.HttpApplication.InitInternal(System.Web.HttpContext, System.Web.HttpApplicationState, System.Reflection.MethodInfo[])+0x18f
System_Web_ni!System.Web.HttpApplicationFactory.GetNormalApplicationInstance(System.Web.HttpContext)+0x138
System_Web_ni!System.Web.HttpApplicationFactory.GetApplicationInstance(System.Web.HttpContext)+0x85
System_Web_ni!System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)+0xc4
System_Web_ni!System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)+0x7c
System_Web_ni!System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)+0x18c
…

That’s interesting. Out of 22 threads, most of them were idle thread pool threads, and 5 of them look something like the above. UrlRewritingNet is creating a regular expression that is getting compiled. That’s an expensive operation, and one that – at most – should only happen on application startup, once for every URL rewrite rule, no more.

It’s possible the dump was taken just as the app pool was recycling, but we took several dumps at different points in time and always saw multiple threads compiling regular expressions for UrlRewritingNet.

0:000> !dumpheap –stat

This command shows memory consumption by type. The first column is the count of objects, the second is the memory footprint. This is a snippet of the highest memory-consuming objects in the heap where the bottom is the highest (System.Byte[]).  Note the bold.

  
   8161     12948160 System.Char[]
    1758     14033336      Free
   20976     14290704 System.Collections.Hashtable+bucket[]
  858215     20597160 System.Reflection.Emit.DynamicScope
  920311     22087464 System.RuntimeTypeHandle
  285987     22878960 UrlRewritingNet.Web.RegExRewriteRule
  858428     27469696 System.Reflection.Emit.LineNumberInfo
  286178     27473088 System.Text.RegularExpressions.Regex
  928586     37143440 System.Collections.ArrayList
  858428     41204544 System.Reflection.Emit.ScopeTree
  859105     41237040 System.Reflection.Emit.SignatureHelper
  858215     48060040 System.Reflection.Emit.DynamicMethod+RTDynamicMethod
  858215     96120080 System.Reflection.Emit.DynamicMethod
  858215    137314400 System.Reflection.Emit.DynamicILGenerator
1737698    158033080 System.String
6007338    192234816 System.Reflection.Emit.GenericFieldInfo
1842110    476240424 System.Object[]
  572154    516188016 System.Reflection.Emit.__FixupData[]
2351800    545836376 System.Int32[]
24239414    581745936 System.RuntimeMethodHandle
2643389    849136768 System.Byte[]

There are 285,987 UrlRewritingNet RegExRewriteRules which account for almost all of the regular expressions (286,178) in the heap!! Again, we only had about 100 URL rewrite rules defined in our configuration file, and somehow there are over a quarter of a million rewrite rule objects in the heap. What the heck?!

ISAPI Rewrite to the rescue

The evidence in the dump files was pretty damning. I pulled open the UrlRewritingNet source code and made sure it wasn’t actually creating a new regular expression for every rule for every request. It wasn’t. What else could be causing it to malfunction? I don’t honestly know. The more rewrite rules there are may be a factor, but that doesn’t particularly make sense.  All I could find was this discussion where a few other people seemed to have similar issues.

We chose to implement Helicon’s ISAPI Rewrite version 3 as the fix. It’s widely used, cheap (free if you can deal with some of the lite version limitations) and fast. After a bit of R&D, we translated the rules, tested, deployed, and held our breath.

The results?

This is the CPU utilization for one week running with UrlRewritingNet. It should be noted that some of the “valleys” where CPU is low may be partially attributed to the server being pulled out of rotation for a period of time due to unresponsiveness.

And this is the first week after implementing ISAPI Rewrite.

Pretty dramatic, eh?

If you happen to be using UrlRewritingNet and are experiencing any performance problems, I highly recommend you to investigate this further and consider other solutions.