Skip to content

Instantly share code, notes, and snippets.

@jasonroelofs
Last active August 29, 2015 14:04
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save jasonroelofs/83e10a2890a2f0955c2f to your computer and use it in GitHub Desktop.
Save jasonroelofs/83e10a2890a2f0955c2f to your computer and use it in GitHub Desktop.
Liquid Profiler benchmarking with CPU and Object
ruby 2.1.2p95 (2014-05-08 revision 45877) [x86_64-darwin13.0]
$ ruby ./performance/benchmark.rb lax
Rehearsal ------------------------------------------------
parse: 3.940000 0.020000 3.960000 ( 3.965286)
parse & run: 8.030000 0.020000 8.050000 ( 8.043193)
-------------------------------------- total: 12.010000sec
user system total real
parse: 3.970000 0.010000 3.980000 ( 3.980672)
parse & run: 7.990000 0.010000 8.000000 ( 7.995005)
$ ruby ./performance/benchmark.rb strict
Rehearsal ------------------------------------------------
parse: 4.670000 0.020000 4.690000 ( 4.698972)
parse & run: 8.800000 0.020000 8.820000 ( 8.806715)
-------------------------------------- total: 13.510000sec
user system total real
parse: 4.680000 0.020000 4.700000 ( 4.694195)
parse & run: 8.760000 0.010000 8.770000 ( 8.776565)
$ ruby ./performance/profile.rb
Profiling in cpu mode...
==================================
Mode: cpu(1000)
Samples: 1692 (0.00% miss rate)
GC: 358 (21.16%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1491 (88.1%) 157 (9.3%) Liquid::Block#render_all
213 (12.6%) 116 (6.9%) Liquid::Variable#lax_parse
286 (16.9%) 114 (6.7%) Liquid::Context#resolve
97 (5.7%) 97 (5.7%) block in Liquid::Variable#lax_parse
95 (5.6%) 95 (5.6%) Liquid::Context#variable_parse
86 (5.1%) 86 (5.1%) block in Liquid::Template#tokenize
1039 (61.4%) 66 (3.9%) Liquid::Block#parse
280 (16.5%) 57 (3.4%) Liquid::Variable#initialize
53 (3.1%) 53 (3.1%) Liquid::Context#has_interrupt?
132 (7.8%) 46 (2.7%) Liquid::Template#tokenize
27 (1.6%) 26 (1.5%) Liquid::If#lax_parse
1334 (78.8%) 25 (1.5%) block in Liquid::Block#render_all
26 (1.5%) 24 (1.4%) Liquid::For#lax_parse
22 (1.3%) 22 (1.3%) Liquid::Context#[]=
27 (1.6%) 21 (1.2%) block in Liquid::Context#variable
19 (1.1%) 17 (1.0%) Liquid::Context#initialize
16 (0.9%) 16 (0.9%) Liquid::StandardFilters#strip_html
15 (0.9%) 15 (0.9%) Liquid::Block#block_delimiter
356 (21.0%) 14 (0.8%) Liquid::Variable#render
141 (8.3%) 14 (0.8%) block in Liquid::Variable#render
Profiling in object mode...
==================================
Mode: object(1)
Samples: 7714400 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
2022100 (26.2%) 1299000 (16.8%) Liquid::Variable#lax_parse
723100 (9.4%) 723100 (9.4%) block in Liquid::Variable#lax_parse
625200 (8.1%) 625200 (8.1%) Liquid::Context#variable_parse
2856100 (37.0%) 597000 (7.7%) Liquid::Block#create_variable
9083600 (117.7%) 474300 (6.1%) Liquid::Block#parse
859000 (11.1%) 438600 (5.7%) Liquid::Template#tokenize
1282700 (16.6%) 421100 (5.5%) Liquid::Context#resolve
420400 (5.4%) 420400 (5.4%) block in Liquid::Template#tokenize
2178900 (28.2%) 300600 (3.9%) Liquid::Variable#render
1046400 (13.6%) 295500 (3.8%) block in Liquid::Variable#render
289100 (3.7%) 289100 (3.7%) Liquid::If#lax_parse
2259100 (29.3%) 238800 (3.1%) block in Liquid::Block#create_variable
204800 (2.7%) 204800 (2.7%) Liquid::StandardFilters#truncatewords
146100 (1.9%) 143500 (1.9%) Liquid::For#lax_parse
131300 (1.7%) 131300 (1.7%) block in Liquid::Context#variable
5942800 (77.0%) 108700 (1.4%) Liquid::Block#render_all
600600 (7.8%) 98500 (1.3%) Liquid::Context#invoke
72300 (0.9%) 72000 (0.9%) Liquid::Context#initialize
683300 (8.9%) 58100 (0.8%) block in Liquid::Context#initialize
9653300 (125.1%) 47600 (0.6%) Liquid::Tag.parse
$ ruby ./performance/profile.rb strict
Profiling in cpu mode...
==================================
Mode: cpu(1000)
Samples: 2495 (0.00% miss rate)
GC: 318 (12.75%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
299 (12.0%) 299 (12.0%) Liquid::Lexer#tokenize
451 (18.1%) 179 (7.2%) Liquid::Context#resolve
2263 (90.7%) 172 (6.9%) Liquid::Block#render_all
127 (5.1%) 127 (5.1%) block in Liquid::Template#tokenize
123 (4.9%) 123 (4.9%) Liquid::Context#variable_parse
230 (9.2%) 103 (4.1%) Liquid::Template#tokenize
479 (19.2%) 103 (4.1%) Liquid::Variable#initialize
1952 (78.2%) 95 (3.8%) Liquid::Block#parse
59 (2.4%) 59 (2.4%) Liquid::Context#has_interrupt?
366 (14.7%) 54 (2.2%) Liquid::Variable#strict_parse
52 (2.1%) 52 (2.1%) Liquid::Lexer#initialize
51 (2.0%) 51 (2.0%) Liquid::Parser#consume
58 (2.3%) 49 (2.0%) block in Liquid::Context#variable
38 (1.5%) 38 (1.5%) Liquid::Context#increment_used_resources
35 (1.4%) 35 (1.4%) Liquid::Context#lookup_and_evaluate
2091 (83.8%) 31 (1.2%) block in Liquid::Block#render_all
30 (1.2%) 30 (1.2%) Liquid::Parser#look
68 (2.7%) 25 (1.0%) Liquid::Context#find_variable
25 (1.0%) 25 (1.0%) Liquid::Context#resource_limits_reached?
21 (0.8%) 21 (0.8%) Liquid::Tag#initialize
Profiling in object mode...
==================================
Mode: object(1)
Samples: 7958500 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1445800 (18.2%) 1445800 (18.2%) Liquid::Lexer#tokenize
625200 (7.9%) 625200 (7.9%) Liquid::Context#variable_parse
1976300 (24.8%) 624100 (7.8%) Liquid::Variable#strict_parse
2810600 (35.3%) 597000 (7.5%) Liquid::Block#create_variable
9795300 (123.1%) 474300 (6.0%) Liquid::Block#parse
859000 (10.8%) 438600 (5.5%) Liquid::Template#tokenize
1282700 (16.1%) 421100 (5.3%) Liquid::Context#resolve
420400 (5.3%) 420400 (5.3%) block in Liquid::Template#tokenize
2178900 (27.4%) 300600 (3.8%) Liquid::Variable#render
295500 (3.7%) 295500 (3.7%) Liquid::Lexer#initialize
1046400 (13.1%) 295500 (3.7%) block in Liquid::Variable#render
2213600 (27.8%) 238800 (3.0%) block in Liquid::Block#create_variable
204800 (2.6%) 204800 (2.6%) Liquid::StandardFilters#truncatewords
131300 (1.6%) 131300 (1.6%) block in Liquid::Context#variable
5942800 (74.7%) 108700 (1.4%) Liquid::Block#render_all
1848100 (23.2%) 106800 (1.3%) Liquid::Parser#initialize
600600 (7.5%) 98500 (1.2%) Liquid::Context#invoke
72300 (0.9%) 72000 (0.9%) Liquid::Context#initialize
68000 (0.9%) 68000 (0.9%) Liquid::Parser#expression
683300 (8.6%) 58100 (0.7%) block in Liquid::Context#initialize
ruby 2.1.2p95 (2014-05-08 revision 45877) [x86_64-darwin13.0]
$ ruby ./performance/benchmark.rb lax
Rehearsal ------------------------------------------------
parse: 4.020000 0.030000 4.050000 ( 4.060480)
parse & run: 8.860000 0.020000 8.880000 ( 8.885599)
-------------------------------------- total: 12.930000sec
user system total real
parse: 3.990000 0.020000 4.010000 ( 4.001778)
parse & run: 8.830000 0.020000 8.850000 ( 8.858403)
$ ruby ./performance/benchmark.rb strict
Rehearsal ------------------------------------------------
parse: 4.710000 0.020000 4.730000 ( 4.727241)
parse & run: 9.750000 0.020000 9.770000 ( 9.776526)
-------------------------------------- total: 14.500000sec
user system total real
parse: 4.810000 0.010000 4.820000 ( 4.824353)
parse & run: 9.720000 0.030000 9.750000 ( 9.755941)
$ ruby ./performance/profile.rb
Profiling in cpu mode...
==================================
Mode: cpu(1000)
Samples: 1539 (0.00% miss rate)
GC: 404 (26.25%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
174 (11.3%) 102 (6.6%) Liquid::Variable#lax_parse
229 (14.9%) 86 (5.6%) Liquid::Context#resolve
84 (5.5%) 84 (5.5%) block in Liquid::Template#tokenize
72 (4.7%) 72 (4.7%) block in Liquid::Variable#lax_parse
63 (4.1%) 63 (4.1%) Liquid::Context#variable_parse
1389 (90.3%) 51 (3.3%) Liquid::Block#render_all
130 (8.4%) 46 (3.0%) Liquid::Template#tokenize
860 (55.9%) 46 (3.0%) Liquid::Block#parse
226 (14.7%) 44 (2.9%) Liquid::Variable#initialize
40 (2.6%) 40 (2.6%) Liquid::Profiler::Timing#start
35 (2.3%) 35 (2.3%) Liquid::Profiler::Timing#finish
31 (2.0%) 29 (1.9%) Liquid::If#lax_parse
41 (2.7%) 29 (1.9%) block in Liquid::Context#variable
28 (1.8%) 28 (1.8%) Liquid::Context#has_interrupt?
21 (1.4%) 21 (1.4%) Liquid::Context#lookup_and_evaluate
19 (1.2%) 19 (1.2%) Liquid::Block#block_delimiter
1338 (86.9%) 18 (1.2%) block in Liquid::Block#render_all
18 (1.2%) 18 (1.2%) Liquid::Context#increment_used_resources
297 (19.3%) 16 (1.0%) Liquid::Variable#render
14 (0.9%) 12 (0.8%) Liquid::StandardFilters#to_date
Profiling in object mode...
==================================
Mode: object(1)
Samples: 8151300 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
2022100 (24.8%) 1299000 (15.9%) Liquid::Variable#lax_parse
723100 (8.9%) 723100 (8.9%) block in Liquid::Variable#lax_parse
625200 (7.7%) 625200 (7.7%) Liquid::Context#variable_parse
2856100 (35.0%) 597000 (7.3%) Liquid::Block#create_variable
9083600 (111.4%) 474300 (5.8%) Liquid::Block#parse
859000 (10.5%) 438600 (5.4%) Liquid::Template#tokenize
1282700 (15.7%) 421100 (5.2%) Liquid::Context#resolve
420400 (5.2%) 420400 (5.2%) block in Liquid::Template#tokenize
2178900 (26.7%) 300600 (3.7%) Liquid::Variable#render
1046400 (12.8%) 295500 (3.6%) block in Liquid::Variable#render
289100 (3.5%) 289100 (3.5%) Liquid::If#lax_parse
2259100 (27.7%) 238800 (2.9%) block in Liquid::Block#create_variable
204800 (2.5%) 204800 (2.5%) Liquid::StandardFilters#truncatewords
146100 (1.8%) 143500 (1.8%) Liquid::For#lax_parse
131300 (1.6%) 131300 (1.6%) block in Liquid::Context#variable
7031100 (86.3%) 108700 (1.3%) Liquid::Block#render_all
120700 (1.5%) 101400 (1.2%) Liquid::Profiler::Timing#initialize
600600 (7.4%) 98500 (1.2%) Liquid::Context#invoke
314500 (3.9%) 98400 (1.2%) Liquid::Profiler#start_token
98400 (1.2%) 98400 (1.2%) Liquid::Profiler::Timing#start
$ ruby ./performance/profile.rb strict
Profiling in cpu mode...
==================================
Mode: cpu(1000)
Samples: 2297 (0.00% miss rate)
GC: 587 (25.56%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
186 (8.1%) 186 (8.1%) Liquid::Lexer#tokenize
328 (14.3%) 134 (5.8%) Liquid::Context#resolve
2006 (87.3%) 111 (4.8%) Liquid::Block#render_all
102 (4.4%) 102 (4.4%) block in Liquid::Template#tokenize
1494 (65.0%) 87 (3.8%) Liquid::Block#parse
83 (3.6%) 83 (3.6%) Liquid::Context#variable_parse
333 (14.5%) 76 (3.3%) Liquid::Variable#initialize
160 (7.0%) 58 (2.5%) Liquid::Template#tokenize
49 (2.1%) 49 (2.1%) Liquid::Profiler::Timing#start
48 (2.1%) 48 (2.1%) Liquid::Parser#consume
45 (2.0%) 45 (2.0%) Liquid::Context#has_interrupt?
252 (11.0%) 43 (1.9%) Liquid::Variable#strict_parse
42 (1.8%) 42 (1.8%) Liquid::Profiler::Timing#finish
40 (1.7%) 40 (1.7%) Liquid::Lexer#initialize
33 (1.4%) 33 (1.4%) Liquid::Context#increment_used_resources
41 (1.8%) 33 (1.4%) block in Liquid::Context#variable
1895 (82.5%) 30 (1.3%) block in Liquid::Block#render_all
27 (1.2%) 27 (1.2%) Liquid::Parser#look
24 (1.0%) 24 (1.0%) Liquid::Context#lookup_and_evaluate
51 (2.2%) 20 (0.9%) Liquid::Context#find_variable
Profiling in object mode...
==================================
Mode: object(1)
Samples: 8395400 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1445800 (17.2%) 1445800 (17.2%) Liquid::Lexer#tokenize
625200 (7.4%) 625200 (7.4%) Liquid::Context#variable_parse
1976300 (23.5%) 624100 (7.4%) Liquid::Variable#strict_parse
2810600 (33.5%) 597000 (7.1%) Liquid::Block#create_variable
9795300 (116.7%) 474300 (5.6%) Liquid::Block#parse
859000 (10.2%) 438600 (5.2%) Liquid::Template#tokenize
1282700 (15.3%) 421100 (5.0%) Liquid::Context#resolve
420400 (5.0%) 420400 (5.0%) block in Liquid::Template#tokenize
2178900 (26.0%) 300600 (3.6%) Liquid::Variable#render
1046400 (12.5%) 295500 (3.5%) block in Liquid::Variable#render
295500 (3.5%) 295500 (3.5%) Liquid::Lexer#initialize
2213600 (26.4%) 238800 (2.8%) block in Liquid::Block#create_variable
204800 (2.4%) 204800 (2.4%) Liquid::StandardFilters#truncatewords
131300 (1.6%) 131300 (1.6%) block in Liquid::Context#variable
7031100 (83.7%) 108700 (1.3%) Liquid::Block#render_all
1848100 (22.0%) 106800 (1.3%) Liquid::Parser#initialize
120700 (1.4%) 101400 (1.2%) Liquid::Profiler::Timing#initialize
600600 (7.2%) 98500 (1.2%) Liquid::Context#invoke
98400 (1.2%) 98400 (1.2%) Liquid::Profiler::Timing#finish
98400 (1.2%) 98400 (1.2%) Liquid::Profiler::Timing#start
ruby 2.1.2p95 (2014-05-08 revision 45877) [x86_64-darwin13.0]
$ ruby ./performance/benchmark.rb lax
Rehearsal ------------------------------------------------
parse: 3.410000 0.020000 3.430000 ( 3.428711)
parse & run: 7.490000 0.010000 7.500000 ( 7.500437)
-------------------------------------- total: 10.930000sec
user system total real
parse: 3.390000 0.020000 3.410000 ( 3.398964)
parse & run: 7.340000 0.010000 7.350000 ( 7.348363)
$ ruby ./performance/benchmark.rb strict
Rehearsal ------------------------------------------------
parse: 4.160000 0.010000 4.170000 ( 4.173766)
parse & run: 8.220000 0.010000 8.230000 ( 8.225072)
-------------------------------------- total: 12.400000sec
user system total real
parse: 4.200000 0.000000 4.200000 ( 4.216356)
parse & run: 8.200000 0.020000 8.220000 ( 8.216050)
$ ruby ./performance/profile.rb
Profiling in cpu mode...
==================================
Mode: cpu(1000)
Samples: 1033 (0.00% miss rate)
GC: 89 (8.62%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
152 (14.7%) 99 (9.6%) Liquid::Variable#lax_parse
230 (22.3%) 86 (8.3%) Liquid::Context#resolve
63 (6.1%) 63 (6.1%) Liquid::Context#variable_parse
792 (76.7%) 60 (5.8%) Liquid::Block#parse
1185 (114.7%) 60 (5.8%) Liquid::Block#render_all
53 (5.1%) 53 (5.1%) block in Liquid::Variable#lax_parse
207 (20.0%) 47 (4.5%) Liquid::Variable#initialize
42 (4.1%) 42 (4.1%) Liquid::Template#tokenize
28 (2.7%) 28 (2.7%) Liquid::Context#has_interrupt?
1125 (108.9%) 23 (2.2%) block in Liquid::Block#render_all
24 (2.3%) 23 (2.2%) Liquid::If#lax_parse
20 (1.9%) 20 (1.9%) Liquid::Context#lookup_and_evaluate
27 (2.6%) 20 (1.9%) Liquid::StandardFilters#to_date
31 (3.0%) 19 (1.8%) block in Liquid::Context#variable
18 (1.7%) 18 (1.7%) Liquid::For#lax_parse
17 (1.6%) 17 (1.6%) Liquid::Context#increment_used_resources
36 (3.5%) 15 (1.5%) Liquid::Context#find_variable
17 (1.6%) 14 (1.4%) Liquid::Block#block_delimiter
12 (1.2%) 12 (1.2%) Liquid::Context#[]=
315 (30.5%) 11 (1.1%) Liquid::Variable#render
Profiling in object mode...
==================================
Mode: object(1)
Samples: 7294000 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
2022100 (27.7%) 1299000 (17.8%) Liquid::Variable#lax_parse
723100 (9.9%) 723100 (9.9%) block in Liquid::Variable#lax_parse
625200 (8.6%) 625200 (8.6%) Liquid::Context#variable_parse
2856100 (39.2%) 597000 (8.2%) Liquid::Block#create_variable
9083600 (124.5%) 474300 (6.5%) Liquid::Block#parse
438600 (6.0%) 438600 (6.0%) Liquid::Template#tokenize
1282700 (17.6%) 421100 (5.8%) Liquid::Context#resolve
2178900 (29.9%) 300600 (4.1%) Liquid::Variable#render
1046400 (14.3%) 295500 (4.1%) block in Liquid::Variable#render
289100 (4.0%) 289100 (4.0%) Liquid::If#lax_parse
2259100 (31.0%) 238800 (3.3%) block in Liquid::Block#create_variable
204800 (2.8%) 204800 (2.8%) Liquid::StandardFilters#truncatewords
146100 (2.0%) 143500 (2.0%) Liquid::For#lax_parse
131300 (1.8%) 131300 (1.8%) block in Liquid::Context#variable
5942800 (81.5%) 108700 (1.5%) Liquid::Block#render_all
600600 (8.2%) 98500 (1.4%) Liquid::Context#invoke
72300 (1.0%) 72000 (1.0%) Liquid::Context#initialize
683300 (9.4%) 58100 (0.8%) block in Liquid::Context#initialize
9653300 (132.3%) 47600 (0.7%) Liquid::Tag.parse
47000 (0.6%) 47000 (0.6%) block in Liquid::Context#find_variable
$ ruby ./performance/profile.rb strict
Profiling in cpu mode...
==================================
Mode: cpu(1000)
Samples: 1713 (0.00% miss rate)
GC: 311 (18.16%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
167 (9.7%) 167 (9.7%) Liquid::Lexer#tokenize
1596 (93.2%) 131 (7.6%) Liquid::Block#render_all
289 (16.9%) 112 (6.5%) Liquid::Context#resolve
1361 (79.5%) 84 (4.9%) Liquid::Block#parse
311 (18.2%) 81 (4.7%) Liquid::Variable#initialize
69 (4.0%) 69 (4.0%) Liquid::Context#variable_parse
63 (3.7%) 63 (3.7%) Liquid::Template#tokenize
227 (13.3%) 57 (3.3%) Liquid::Variable#strict_parse
47 (2.7%) 47 (2.7%) Liquid::Context#has_interrupt?
1465 (85.5%) 45 (2.6%) block in Liquid::Block#render_all
37 (2.2%) 37 (2.2%) Liquid::Parser#consume
42 (2.5%) 31 (1.8%) block in Liquid::Context#variable
26 (1.5%) 26 (1.5%) Liquid::Context#increment_used_resources
24 (1.4%) 24 (1.4%) Liquid::Block#block_delimiter
20 (1.2%) 20 (1.2%) Liquid::Context#lookup_and_evaluate
19 (1.1%) 19 (1.1%) Liquid::Context#resource_limits_reached?
18 (1.1%) 18 (1.1%) Liquid::Parser#look
379 (22.1%) 18 (1.1%) Liquid::Variable#render
18 (1.1%) 18 (1.1%) Liquid::Lexer#initialize
45 (2.6%) 16 (0.9%) Liquid::Context#find_variable
Profiling in object mode...
==================================
Mode: object(1)
Samples: 7538100 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1445800 (19.2%) 1445800 (19.2%) Liquid::Lexer#tokenize
625200 (8.3%) 625200 (8.3%) Liquid::Context#variable_parse
1976300 (26.2%) 624100 (8.3%) Liquid::Variable#strict_parse
2810600 (37.3%) 597000 (7.9%) Liquid::Block#create_variable
9795300 (129.9%) 474300 (6.3%) Liquid::Block#parse
438600 (5.8%) 438600 (5.8%) Liquid::Template#tokenize
1282700 (17.0%) 421100 (5.6%) Liquid::Context#resolve
2178900 (28.9%) 300600 (4.0%) Liquid::Variable#render
295500 (3.9%) 295500 (3.9%) Liquid::Lexer#initialize
1046400 (13.9%) 295500 (3.9%) block in Liquid::Variable#render
2213600 (29.4%) 238800 (3.2%) block in Liquid::Block#create_variable
204800 (2.7%) 204800 (2.7%) Liquid::StandardFilters#truncatewords
131300 (1.7%) 131300 (1.7%) block in Liquid::Context#variable
5942800 (78.8%) 108700 (1.4%) Liquid::Block#render_all
1848100 (24.5%) 106800 (1.4%) Liquid::Parser#initialize
600600 (8.0%) 98500 (1.3%) Liquid::Context#invoke
72300 (1.0%) 72000 (1.0%) Liquid::Context#initialize
68000 (0.9%) 68000 (0.9%) Liquid::Parser#expression
683300 (9.1%) 58100 (0.8%) block in Liquid::Context#initialize
10654600 (141.3%) 47600 (0.6%) Liquid::Tag.parse
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment