Shopify/liquid — pull request #382 by jasonhl (2014-07-16 20:40:44+00:00)
Title: Cache parsed markup for variables in LRU

Here's the current benchmark results for liquid/master on my box:

```
user system total real
parse: 2.090000 0.000000 2.090000 ( 2.095237)
parse & run: 4.620000 0.020000 4.640000 ( 4.642556)
```

Here is the cpu profile:
```
==================================
Mode: cpu(1000)
Samples: 1054 (1.13% miss rate)
GC: 82 (7.78%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
154 (14.6%) 100 (9.5%) Liquid::Variable#lax_parse
924 (87.7%) 88 (8.3%) Liquid::Block#parse
178 (16.9%) 77 (7.3%) Liquid::Context#variable
252 (23.9%) 74 (7.0%) Liquid::Context#resolve
66 (6.3%) 66 (6.3%) Liquid::Template#tokenize
54 (5.1%) 54 (5.1%) block in Liquid::Variable#lax_parse
199 (18.9%) 39 (3.7%) Liquid::Variable#initialize
43 (4.1%) 36 (3.4%) block in Liquid::Context#variable
28 (2.7%) 28 (2.7%) Liquid::Context#has_interrupt?
28 (2.7%) 28 (2.7%) Liquid::Context#lookup_and_evaluate
1149 (109.0%) 25 (2.4%) block in Liquid::Block#render_all
24 (2.3%) 24 (2.3%) block in Liquid::Context#find_variable
27 (2.6%) 23 (2.2%) Liquid::If#lax_parse
1171 (111.1%) 22 (2.1%) Liquid::Block#render_all
22 (2.1%) 22 (2.1%) Liquid::For#lax_parse
17 (1.6%) 17 (1.6%) Liquid::Context#increment_used_resources
16 (1.5%) 16 (1.5%) Liquid::StandardFilters#strip_html
11 (1.0%) 11 (1.0%) Liquid::Context#resource_limits_reached?
307 (29.1%) 11 (1.0%) Liquid::Variable#render
10 (0.9%) 10 (0.9%) Liquid::StandardFilters#truncatewords
```

And the object allocation profile:
```
==================================
Mode: object(1)
Samples: 9639300 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1947200 (20.2%) 1462300 (15.2%) Liquid::Context#variable
2185900 (22.7%) 1433400 (14.9%) Liquid::Variable#lax_parse
833800 (8.7%) 833800 (8.7%) Liquid::Context#has_interrupt?
10194700 (105.8%) 806100 (8.4%) Liquid::Block#parse
752500 (7.8%) 752500 (7.8%) block in Liquid::Variable#lax_parse
2944500 (30.5%) 521600 (5.4%) Liquid::Block#create_variable
438600 (4.6%) 438600 (4.6%) Liquid::Template#tokenize
480300 (5.0%) 433300 (4.5%) Liquid::Context#find_variable
2368300 (24.6%) 421100 (4.4%) Liquid::Context#resolve
3075100 (31.9%) 300600 (3.1%) Liquid::Variable#render
1075400 (11.2%) 295500 (3.1%) block in Liquid::Variable#render
289100 (3.0%) 289100 (3.0%) Liquid::If#lax_parse
2422900 (25.1%) 238800 (2.5%) block in Liquid::Block#create_variable
204800 (2.1%) 204800 (2.1%) Liquid::StandardFilters#truncatewords
146100 (1.5%) 143500 (1.5%) Liquid::For#lax_parse
10927100 (113.4%) 108700 (1.1%) Liquid::Block#render_all
600600 (6.2%) 98500 (1.0%) Liquid::Context#invoke
70700 (0.7%) 70700 (0.7%) Liquid::Block#block_delimiter
48300 (0.5%) 48000 (0.5%) Liquid::Context#initialize
10764400 (111.7%) 47600 (0.5%) Liquid::Tag.parse
```

Liquid::Context#variable is responsible for the most allocations and is the third most prominent CPU hog. In addition, live profiles of Shopify identify it as allocating ~4.5% of the total Ruby objects (!) and taking ~1.5-2% of the CPU. In short, we call this *a lot* and it's reasonably expensive.

Nearly all the objects and good chunk of the CPU comes down to this line:

```
parts = markup.scan(VariableParser)
```

All this does is take a string and break it up into an array using . and [] as delimiters. There's no real way to remove the allocation here -- doing this via regexp is going to create objects. Since Liquid templates are likely to be seeing the same variables over and over and over again, I introduced an LRU cache for the results of markup.scan(...). That way, the bits which are done repeatedly will be fast and allocate few objects while the unique snowflakes will be no worse than before.

The results are pretty good... benchmark:

```
user system total real
parse: 2.080000 0.000000 2.080000 ( 2.081288)
parse & run: 4.480000 0.000000 4.480000 ( 4.487226)
```

cpu profile:
```
==================================
Mode: cpu(1000)
Samples: 1057 (1.31% miss rate)
GC: 71 (6.72%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
183 (17.3%) 119 (11.3%) Liquid::Variable#lax_parse
971 (91.9%) 92 (8.7%) Liquid::Block#parse
217 (20.5%) 84 (7.9%) Liquid::Context#resolve
64 (6.1%) 64 (6.1%) block in Liquid::Variable#lax_parse
63 (6.0%) 63 (6.0%) Liquid::Template#tokenize
34 (3.2%) 34 (3.2%) LruRedux::Cache#[]
225 (21.3%) 32 (3.0%) Liquid::Variable#initialize
28 (2.6%) 28 (2.6%) Liquid::Context#has_interrupt?
1069 (101.1%) 25 (2.4%) block in Liquid::Block#render_all
33 (3.1%) 24 (2.3%) block in Liquid::Context#variable
24 (2.3%) 24 (2.3%) Liquid::Context#lookup_and_evaluate
22 (2.1%) 22 (2.1%) Liquid::Context#increment_used_resources
28 (2.6%) 21 (2.0%) Liquid::If#lax_parse
20 (1.9%) 20 (1.9%) block in Liquid::Context#find_variable
20 (1.9%) 19 (1.8%) Liquid::For#lax_parse
16 (1.5%) 16 (1.5%) Liquid::Context#resource_limits_reached?
133 (12.6%) 15 (1.4%) Liquid::Context#variable
15 (1.4%) 15 (1.4%) Liquid::Tag#initialize
282 (26.7%) 15 (1.4%) Liquid::Variable#render
14 (1.3%) 14 (1.3%) Liquid::Template.error_mode
```

object profile:
```
==================================
Mode: object(1)
Samples: 8811300 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
2185900 (24.8%) 1433400 (16.3%) Liquid::Variable#lax_parse
833800 (9.5%) 833800 (9.5%) Liquid::Context#has_interrupt?
10194700 (115.7%) 806100 (9.1%) Liquid::Block#parse
752500 (8.5%) 752500 (8.5%) block in Liquid::Variable#lax_parse
2944500 (33.4%) 521600 (5.9%) Liquid::Block#create_variable
438600 (5.0%) 438600 (5.0%) Liquid::Template#tokenize
480300 (5.5%) 433300 (4.9%) Liquid::Context#find_variable
1540300 (17.5%) 421100 (4.8%) Liquid::Context#resolve
321900 (3.7%) 321900 (3.7%) LruRedux::Cache#[]
1119200 (12.7%) 312400 (3.5%) Liquid::Context#variable
2434900 (27.6%) 300600 (3.4%) Liquid::Variable#render
1058600 (12.0%) 295500 (3.4%) block in Liquid::Variable#render
289100 (3.3%) 289100 (3.3%) Liquid::If#lax_parse
2422900 (27.5%) 238800 (2.7%) block in Liquid::Block#create_variable
204800 (2.3%) 204800 (2.3%) Liquid::StandardFilters#truncatewords
146100 (1.7%) 143500 (1.6%) Liquid::For#lax_parse
8876400 (100.7%) 108700 (1.2%) Liquid::Block#render_all
600600 (6.8%) 98500 (1.1%) Liquid::Context#invoke
70700 (0.8%) 70700 (0.8%) Liquid::Block#block_delimiter
48300 (0.5%) 48000 (0.5%) Liquid::Context#initialize
```

So, that's 828,000 less objects and a ~150 ms difference in cumulative CPU time.

There's a couple things I wasn't sure of here:

* Is 10,000 a reasonable size for the LRU?
* The LRU cache is not thread safe (I don't see any reason why it would need the extra overhead....) -- should it be?

@Shopify/liquid