Mini Me-fication in System.Web.Optimization RC is Evil

miniI am working on a MVC4 RC application within the Visual Studio 2012 RC. I started to notice my web pages were starting to get a bit sluggish with regard to response times. I found that I could not get any page to return in less than 1 second. So I stated to do a bit of digging – I created a TestController controller with a single Index() action and a view which did not use any master page/layout. The page, according to FireBug was 2-3ms coming from IISExpress running on my local dev machine. Now the view was a very simple page with a DocType, header, and body without any content so this is about as basic as you can get.

I decided to start adding components back into the page and the first change which I knew was different to my setup was the inclusion of Bundling from the System.Web.Optimization namespace. My Bundling configuration consisted of a the recommended BundleConfig class within the App_Start folder of my MVC project with a single bundle configured like here:

bundles.Add(new ScriptBundle("~/content/scripts/tax").Include(
                        "~/content/scripts/modernizr-*",
                        "~/content/scripts/jquery-ui-1.8.17.min.js",
                        "~/content/scripts/jquery.unobtrusive-ajax.min.js",       
                        "~/content/scripts/jquery.validate.unobtrusive.min.js",
                        "~/content/scripts/jquery.fancybox.pack.js",
                        "~/content/scripts/bootbox.min.js",
                        "~/content/scripts/jquery.placeholder.min.js",
                        "~/content/scripts/jquery.qtip.min.js",
                        "~/content/scripts/jquery.maskedinput-1.3.min.js",
                        "~/content/scripts/autoNumeric-1.7.4.js",
                        "~/content/scripts/bootstrap.min.js",
                        "~/content/scripts/site.js"
                        ));

 

With this configuration in place I decided to include the render method into my view like so:

@{
    Layout = null;
}
<!DOCTYPE html>
<html>
<head>
    <meta name="viewport" content="width=device-width" />
    <title>Index</title>
     @Scripts.Render("~/content/scripts/tax")
</head>
<body>
    <div>
    </div>
</body>
</html>

 

With debug=”false” I made several requests and again used Fire Bug and the page response time frequently was about 1 second – in fact in over 20 runs it ranged from 653ms – over 2 seconds with the majority being just above 1 second.

fb1

I then changed to debug=”true” believing that this would make a positive difference however to my surprise there was no improvement in performance and if anything it was worse when looking at just the original page response times. Again over about 20 runs they ranged from ~800ms – to about 2.4 seconds.

fb2 

For my last test I decided to take the script tags from the “view Source” of the last test and past those into the header and remove the Razor call to Render – so now my page looks like this:

 

@{
    Layout = null;
}
<!DOCTYPE html>
<html>
<head>
    <meta name="viewport" content="width=device-width" />
    <title>Index</title>
    <script src="/content/scripts/jquery-ui-1.8.17.min.js" type="text/javascript"></script>
    <script src="/content/scripts/jquery.unobtrusive-ajax.min.js" type="text/javascript"></script>
    <script src="/content/scripts/jquery.validate.unobtrusive.min.js" type="text/javascript"></script>
    <script src="/content/scripts/modernizr-2.0.6-development-only.js" type="text/javascript"></script>
    <script src="/content/scripts/jquery.fancybox.pack.js" type="text/javascript"></script>
    <script src="/content/scripts/bootbox.min.js" type="text/javascript"></script>
    <script src="/content/scripts/jquery.placeholder.min.js" type="text/javascript"></script>
    <script src="/content/scripts/jquery.qtip.min.js" type="text/javascript"></script>
    <script src="/content/scripts/jquery.maskedinput-1.3.min.js" type="text/javascript"></script>
    <script src="/content/scripts/autoNumeric-1.7.4.js" type="text/javascript"></script>
    <script src="/content/scripts/bootstrap.min.js" type="text/javascript"></script>
    <script src="/content/scripts/site.js" type="text/javascript"></script>
</head>
<body>
    <div>
    </div>
</body>
</html>

With the page configured like the above the tests ran between 3ms and 5ms with most returning in 4ms.

fb3

So at this point I decided to use the Visual Studio 2012 Profiler. Looking at the hot path, which, without going into allot of detail, is basically the most interesting stack/path to start your investigation. What I found was ReportError() coming out of the WebGrease assembly was on the top of the stack the most during sampling with the frame just below that one being from the same assembly but named JSParser.ParseStatement(). To things concerned me about seeing this 1) there appears to be some kind of error happening during a parse of the Javascript, and 2) why the heck are we parsing JavaScript out of these files each time we make a request to render a bundle and keep in mind, we are in debug=”true” mode here so no minification is enabled here.

prof1

I decided to start adding scripts into my bundles in small increments to see if there was a tipping point or a cost per script added. I documented my results in the table below:

Number of Total Scripts Average Response Time (Debug=true)
1 12ms
4 40ms
5 56ms
7 91ms
11 102ms
12 900ms

 

So there was a major jump when I added the 12th script. Of course not all scripts are created equal so I decided to create the bundle with just this single script and found that requests with must this one script ran at about 650ms. This script, which appears to be the issue, was named jquery-ui.1.8.17.min.js Since this file was already minified (as were several of the others in the original bundle and in the tests included in the table above) I substituted for the debug version of this script in my bundle configuration and the request ran at about 133ms on average which was a huge improvement.

Thinking the already minified script files might have been an issue I created a bundle with only debug versions of each of those 12 JavaScript files and the performance was decent at about 158ms per request with debug=”true”.

fb4

With debug=”false” and for the primary page I noticed the times were right at the same times, about 158ms on average.

fb5

So at this point I have made almost a 10x performance improvement by moving from including already minified js files to debug js files into my bundle. Now lets stress the application again with the Profiler running.

prof2

As you can see the top method on the hot path has changed however that as well as the second method JSParser.ParseStatements() coming out of the WebGrease assembly.

Finally I decided to grab a memory dump of the iisexpress process during my stress run and unfortunately my suspicion was again confirmed:

<snip>

0463ad14 0a5adeff 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.VariableDeclaration..ctor(Microsoft.Ajax.Utilities.Context, Microsoft.Ajax.Utilities.JSParser, System.String, Microsoft.Ajax.Utilities.Context, Microsoft.Ajax.Utilities.AstNode, System.Reflection.FieldAttributes, Boolean)+0x2cd

0463ad3c 0a5add46 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.VariableDeclaration..ctor(Microsoft.Ajax.Utilities.Context, Microsoft.Ajax.Utilities.JSParser, System.String, Microsoft.Ajax.Utilities.Context, Microsoft.Ajax.Utilities.AstNode, System.Reflection.FieldAttributes)+0x37

0463ae34 0a710352 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseIdentifierInitializer(Microsoft.Ajax.Utilities.JSToken, System.Reflection.FieldAttributes)+0x586

0463b014 0a5a0800 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseForStatement()+0x1b2

0463b204 0a5a57ae 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseStatement(Boolean)+0x2b0

0463b464 0a5a4a04 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseFunction(Microsoft.Ajax.Utilities.FunctionType, Microsoft.Ajax.Utilities.Context)+0xb1e

0463b854 0a5a2c7e 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseLeftHandSideExpression(Boolean)+0x1c5c

0463b9f4 0a5abd67 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseUnaryExpression(Boolean ByRef, Boolean)+0xcb6

0463ba18 0a5a4610 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseExpression(Boolean)+0x37

0463be04 0a5a2c7e 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseLeftHandSideExpression(Boolean)+0x1868

0463bfa4 0a5abd67 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseUnaryExpression(Boolean ByRef, Boolean)+0xcb6

0463bfc8 0a5abab9 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseExpression(Boolean)+0x37

0463c070 0a5a6dab 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseExpressionList(Microsoft.Ajax.Utilities.JSToken)+0x199

0463c230 0a5a4b75 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.MemberExpression(Microsoft.Ajax.Utilities.AstNode, System.Collections.Generic.List`1<Microsoft.Ajax.Utilities.Context>)+0xc3

0463c620 0a5a2c7e 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseLeftHandSideExpression(Boolean)+0x1dcd

0463c7c0 0a5a0d84 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseUnaryExpression(Boolean ByRef, Boolean)+0xcb6

0463c9b4 0a5a57ae 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseStatement(Boolean)+0x834

0463cc14 0a5a4a04 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseFunction(Microsoft.Ajax.Utilities.FunctionType, Microsoft.Ajax.Utilities.Context)+0xb1e

0463d004 0a5a2c7e 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseLeftHandSideExpression(Boolean)+0x1c5c

0463d1a4 0a5a4c54 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseUnaryExpression(Boolean ByRef, Boolean)+0xcb6

0463d1c4 0a5a3700 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseExpression()+0x34

0463d5b0 0a5a2c7e 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseLeftHandSideExpression(Boolean)+0x958

0463d750 0a5a0d84 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseUnaryExpression(Boolean ByRef, Boolean)+0xcb6

0463d944 0800d6c3 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseStatement(Boolean)+0x834

0463da14 0800c0b5 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.ParseStatements()+0x103

0463da80 08009bd2 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.JSParser.Parse(Microsoft.Ajax.Utilities.CodeSettings)+0xad

0463db10 08009a67 00000000 00000000 00000000 WebGrease!Microsoft.Ajax.Utilities.Minifier.MinifyJavaScript(System.String, Microsoft.Ajax.Utilities.CodeSettings)+0xea

0463db70 07f48d67 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.JsMinify.Process(System.Web.Optimization.BundleContext, System.Web.Optimization.BundleResponse)+0x137

0463dbd0 07f471d6 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.Bundle.ApplyTransforms(System.Web.Optimization.BundleContext, System.String, System.Collections.Generic.IEnumerable`1<System.IO.FileInfo>)+0xd7

0463dc28 07f46d35 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.Bundle.GenerateBundleResponse(System.Web.Optimization.BundleContext)+0x12e

0463dcc8 07f468f2 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.BundleResolver.GetBundleContents(System.String)+0x11d

0463ddac 07f4648c 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.AssetManager.EliminateDuplicatesAndResolveUrls(System.Collections.Generic.IEnumerable`1<System.String>)+0x182

0463de5c 0800965e 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.AssetManager.DeterminePathsToRender(System.Collections.Generic.List`1<Asset>)+0x254

0463dee4 07f46024 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.AssetManager.RenderScripts(System.Collections.Generic.List`1<Asset>)+0x46

0463df14 08009537 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.AssetManager.RenderExplicit(Boolean, System.String[])+0xdc

0463df2c 07f45892 00000000 00000000 00000000 System_Web_Optimization!System.Web.Optimization.Scripts.Render(System.String[])+0x37

<snip>

Conclusion

I find it very concerning that it appears JavaScript is being parsed each time a page request is made to load my 12 javascript files whenever they are included in a bundle with or without the debug=true or debug=false compilation flags. By doing this it would appear it takes a blank page about 158ms compared to the same page without Bundling taking 4ms or about 1/40th the amount of time. Fortunately for my project I am still months out of shipping and I am confident Microsoft will get this addressed before we see an RTM.

Post to Twitter Post to Facebook Post to LinkedIn Post to Delicious Post to Digg

12 thoughts on “Mini Me-fication in System.Web.Optimization RC is Evil”

  1. Hi Howard. Where do I find the update? I have tried nuget to Update-Package however there isn’t any updates available.

  2. Shane, in the NuGet Package Manager dialog box be sure to enable "Include Prelease" so it shows packages that are not RTMed yet such as Optimization.

  3. I installed yesterday – yea I was looking for an upgrade notification but never got one – the issue appears resolved, the performance is much better with Optimization on or off.

    Thanks for the quick turn around on a fix and publish.

Comments are closed.