Template compilation seems slower with 2.0

[sferencik]

I've upgraded to 2.0.3 and it seems the compilation has slowed down about 2x. It's not a big deal, just want to raise this because it doesn't match the expectations.

I have not benchmarked this properly, just timed how much it takes to compile my large repo: the overall time has gone up from 13-15s to 22-31s. I'll try to provide some clearer numbers later.

[oformaniuk]

Hello @sferencik
There's continuous benchmark running at each push to master. If you can provide an example of slow compiling template I'd be able to have a look.

[oformaniuk]

@sferencik, any updates?

[sferencik]

I'll try to get you some templates. I'm trying to identify the ones that would illustrate this best. I'm choosing from 1,600+ pairs of (email subject, email HTML body), i.e. 3,336 Handlebars sources. (The email subjects are often just plain text with no Handlebars mark-up.) For each of these 3,336 sources, I've run HandlebarsEnvironment.Compile() ten times, with each of Handlebars.Net 1.10 and 2.0.

What I'm seeing is this: if I compare the 3,336 minimum compile times (the fastest of the 10 compiles of each template with Handlebars 1.10 versus 2.0), about 27% have speeded up, the rest have slowed down. Here is the CDF of the ratio of the fastest times (>1 means slow-down):

If I compare the 3,336 average compile times (the average of the 10 compiles of each templates), about 22% have speeded up, the rest have slowed down. Here is the CDF of the ratio of the average times:

I am surprised by the large spread; maybe I need to run them more than 10 times each... Or I'll just pick one or two candidates and send them to you...

[sferencik]

OK, so here's one of the many files that show a 20x slow-down in compilation. I've run this many more times (200x with each of Handlebars 1.10 and 2.0 to increase the confidence) and for this specific file there's a 50x slow-down.

https://gist.github.com/sferencik/2e27f55c9439324ef1568d184f1955b1

Specifically, this file:

• with Handlebars 1.10: it compiles in 1.91ms on average (1.43ms min, 4.62 max, 0.523ms stddev)
• with Handlebars 2.0: it compiles in 102ms on average (60.8ms min, 1980ms max, 136ms stddev)

UPDATE: I've uploaded a new version of the gist. Ran the test again, this time the numbers are not so bad (16x slow-down, instead of 50x):

• with Handlebars 1.10: it compiles in 1.88ms on average (1.57ms min, 2.09 max, 0.0963 relative stddev)
• with Handlebars 2.0: it compiles in 32.8ms on average (25.8ms min, 45.0ms max, 0.171 relative stddev)

[sferencik]

@zjklee I hope this helps. TBH I don't have the time to dig into the slow-down, nor do I have a very good understanding of the differences that 2.0 introduced.

This is not urgent, we can live with the slow-down. However, it would be good, for the sake of the project, to try and zoom in on what's going on. If I find time, I may try to create a test that shows this slow-down, and bisect the Handlebars.Net code around the 2.0 release. That would help at least partially, and doesn't require very deep understanding.

[jrlost]

When updating, I also noticed this. It seems that smaller templates (those with fewer handlebar expressions) seem to have an interesting performance decrease. Taking the gist @sferencik provided, I made a very simple benchmark using Benchmark.Net.

public class TestCompilation {
    private string _templateBody;
    private IHandlebars _handlebars;

    [GlobalSetup]
    public void GlobalSetup() {
        _handlebars = Handlebars.Create();
        _templateBody = "{{reseller.companyName}}";
    }

    [Benchmark]
    public object CompileTemplate() {
        return _handlebars.Compile(_templateBody);
    }
}

changing the number of expressions appears to produce linear compilation time growth until a certain point.

public class TestCompilation {
    private string _templateBody;
    private IHandlebars _handlebars;

    [GlobalSetup]
    public void GlobalSetup() {
        _handlebars = Handlebars.Create();
        _templateBody = "{{reseller.companyName}}{{reseller.companyName}}{{reseller.companyName}}{{reseller.companyName}}{{reseller.companyName}}";
    }

    [Benchmark]
    public object CompileTemplate() {
        return _handlebars.Compile(_templateBody);
    }
}

Results:
1 expression:

Method	Mean	Error	StdDev
CompileTemplate	1.047 ms	0.0205 ms	0.0281 ms

5 expressions:

Method	Mean	Error	StdDev
CompileTemplate	4.375 ms	0.0986 ms	0.2829 ms

10 expressions:

Method	Mean	Error	StdDev
CompileTemplate	9.046 ms	0.1759 ms	0.2348 ms

20 expressions:

Method	Mean	Error	StdDev
CompileTemplate	20.87 ms	0.411 ms	0.858 ms

40 expressions:

Method	Mean	Error	StdDev
CompileTemplate	27.86 ms	0.522 ms	0.558 ms

80 expressions:

Method	Mean	Error	StdDev
CompileTemplate	31.93 ms	0.408 ms	0.341 ms

Switching to 1.11.5 and running the exact same process results in:

1 expression:

Method	Mean	Error	StdDev
CompileTemplate	493.5 us	6.17 us	5.47 us

5 expressions:

Method	Mean	Error	StdDev
CompileTemplate	665.3 us	6.86 us	5.72 us

10 expressions:

Method	Mean	Error	StdDev
CompileTemplate	872.8 us	9.61 us	8.02 us

20 expressions:

Method	Mean	Error	StdDev
CompileTemplate	1.368 ms	0.0258 ms	0.0680 ms

40 expressions:

Method	Mean	Error	StdDev
CompileTemplate	2.255 ms	0.0413 ms	0.0386 ms

80 expressions:

Method	Mean	Error	StdDev
CompileTemplate	4.610 ms	0.0915 ms	0.2425 ms

Keep in mind, this appears to only be the case for very simple templates. Templates with partials, block helpers, sub-expressions, etc... appear to compile significantly faster. Was just adding this as further evidence to the claim that v2 is slower; it only appears to be slower to a point.