Performance Problem on Compile

[PaulGrimshaw]

I appear to have an odd performance issue on the compile step. I am running a web application on Amazon EC2. The "compile" step is taking huge amounts of time to compute, and is causing the CPU to fire on 100% for several seconds (30sec + in some cases). This is with the simplest of templates.

This is the code that is running:

const string template = "Hello {{name}}, how are you today?  Welcome to this App {{name}}";
            dynamic obj = new {Name = "Mr Smith",OtherField="Other value with a bit more text"};
            using (MiniProfiler.Current.Step("Prepping Template")) {
                var compiler = new FormatCompiler();
                var keys = new HashSet<string>();
                compiler.PlaceholderFound += (o, e) => keys.Add(e.Key);

                using (MiniProfiler.Current.Step("Compiling Template")) {
                    var generator = compiler.Compile(template);
                    using (MiniProfiler.Current.Step("Template key not found handler")) {
                        generator.KeyNotFound += (objR, args) => {
                            args.Substitute = String.Format("[Field \"{0}\" of path \"{1}\" not found!]", args.MissingMember, args.Key);
                            args.Handled = true;
                        };

                        using (MiniProfiler.Current.Step("Fetching Expando Object")) {

                            using (MiniProfiler.Current.Step("Rendering Template")) {
                                var result = generator.Render(new CustomFormatProvider(), obj);
                            }
                        }
                    }
                }

And below you can see the times for each step output by MiniProfiler:

[jehugaleahsa]

Hmm. I will run this as soon as I get a chance. Although it doesn't make a lot of sense that it would run slow. I know the DLR can take a while to load the first time but it's only the first time.

Perhaps tracking the context added some overhead I haven't experienced in my own projects yet. On May 1, 2013 2:32 AM, "PaulGrimshaw" notifications@github.com wrote:

I appear to have an odd performance issue on the compile step. I am running a web application on Amazon EC2. The "compile" step is taking huge amounts of time to compute, and is causing the CPU to fire on 100% for several seconds (30sec + in some cases). This is with the simplest of templates.

This is the code that is running:

const string template = "Hello {{name}}, how are you today? Welcome to this App {{name}}"; dynamic obj = new {Name = "Hello",OtherField="Other value with a bit more text"}; using (MiniProfiler.Current.Step("Prepping Template")) { var compiler = new FormatCompiler(); var keys = new HashSet(); compiler.PlaceholderFound += (o, e) => keys.Add(e.Key);

            using (MiniProfiler.Current.Step("Compiling Template")) {
                var generator = compiler.Compile(template);
                using (MiniProfiler.Current.Step("Template key not found handler")) {
                    generator.KeyNotFound += (objR, args) => {
                        args.Substitute = String.Format("[Field \"{0}\" of path \"{1}\" not found!]", args.MissingMember, args.Key);
                        args.Handled = true;
                    };

                    using (MiniProfiler.Current.Step("Fetching Expando Object")) {

                        using (MiniProfiler.Current.Step("Rendering Template")) {
                            var result = generator.Render(new CustomFormatProvider(), obj);
                        }
                    }
                }
            }

And below you can see the times for each step output by MiniProfiler:

[image: Screenshot]https://s3.amazonaws.com/quick-tracks/Public+Images/MiniProfiler+Screen+Shot.png?AWSAccessKeyId=ASIAJE6XVVX72GWDWWXA&Expires=1367389972&Signature=A%2BDit/EnsAGFpGIC6tWH/CW/VKs%3D&x-amz-security-token=AQoDYXdzEHAasAIPoxLJKfShW2dSGUkZfHS8pieC03c%2BXlVtItRTERZYK08EjLDrIyf1NOJDwHL/7%2BK2xVI1QlImz1U4F35N5LJDp0Hlc4%2BSjTG1/cDoUl03Z9rGwAz5cZurX4LqBxRz4HD1pArZRZO187UfRD0AVgI9peQ3oKdQxulG0xA0g35cmFpIRTVx7mVxPLAYQEXvbYBel5aXRxd/wE1QqcWorflQFkpOL58oPWMbjc11hhDBB4adXPZCUggGVPxqV5m17jA4NjJfPlwjCBHrYTX2QV1qntz8S0ol9wlt0N3Ueby3jYbSSJ%2BYYceMuVgO63RgAfLQh3svGV5GQI7DhzXpBHaUS9IAbD8dketNdfIdYNXj4ugXIKCl4MUmiA0EIAzfD4fnuIpp93RKdLnh4JDY34krILrrgowFFormat: [image: Screenshot] http://url

— Reply to this email directly or view it on GitHubhttps://github.com/jehugaleahsa/mustache-sharp/issues/3 .

[PaulGrimshaw]

It runs considerably faster on my dev machine, although the times are still slower than one would expect.

What do you mean by "the DLR can take a while to load the first time"? As it's a web project, the code above runs entirely every request, sometimes multiple times...

[jehugaleahsa]

Doing a little profiling on my end. It looks like most of the time is spent building the Regex that is used to find the tags. The good news is that it appears that passing RegexOptions.Compiled could be the issue. I was using this because the assumption was you'd run the same generator many times.

What I will do is provide an Optimize property that will turn this on and off. Once I publish it, you can see if setting it to false will improve performance. If that doesn't work, we'll try something else.

[jehugaleahsa]

What I find interesting is that using the Compiled option seems to run slower most of the time. Only when you use the same Regex a few 100,000 times does there seem to be any benefit whatsoever.

I'm just going to remove the Compiled option for now and add the flag if it is needed. Premature optimization is the root of all evil, I guess.

[jehugaleahsa]

I also just realized that the namespace is mustache which doesn't follow .NET namespace naming conventions. It should be capitalized. I may change this at some point in the future (perhaps v1). The newest version is available on NuGet and GitHub.

Please give me feedback so I know to close the issue or keep looking for other opportunities to optimize.

[PaulGrimshaw]

Wow, factors of 100 better. The compilation has become insignificant! Many thanks for this!

[PaulGrimshaw]

Namespace change is fine by me, Resharper will clean it all up for us