Fixing a performance issue with the mustache gem

@alicebartlett and I gave this talk at LRUG, on Monday 12th October 2015.

Transcript

1. fixing a performance issue with the mustache gem (a bit less boring than it sounds)
2. @alicebartlett & @evilstreak
3. We used to work at GDS, on gov.uk
4. In this talk: - Adding a feature - Finding a bug - working around the bug - fixing the bug
5. GOV.uk is the best place to find government services and information
6. These are Manuals They are multi- page long form documents
7. New feature: search within a manual
8. This is search within a manual A list of results from a Manual with a nested list of results from the rest of GOV.UK
9. From this:
10. To this: From this:
12. Search pages use mustache (specifically: the ruby implementation of mustache via the mustache gem)
13. From this:
14. To this: From this:
15. To this: then from this:
16. This is very uninteresting.
17. Using partials in this way is in the docs: from: https://mustache.github.io/mustache.5.html#Partials
18. full PR is here: https://github.com/alphagov/frontend/pull/784
19. Time to deploy!
20. This should have been straightforward
22. -
23. -
24. We deploy to staging
25. We proceed to production
26. Slowly, shit hits the fan.
27. -
28. We rollback and investigate on staging
29. Breaking things isn’t bad if you have a good plan to recover
30. Profiling
31. We found out the problem was this CPU spike
32. # Profile the code RubyProf.start ... [code to profile] ... result = RubyProf.stop # Print a flat profile to text printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT) Measuring code with ruby-prof is easy
33. Profile of our code %self total self wait child calls name 5.41 0.271 0.086 0.000 0.185 675 Mustache::Parser#scan_tags 3.90 0.062 0.062 0.000 0.000 36 BasicObject#instance_eval 3.34 1.031 0.053 0.000 0.978 1 ActionView::CompiledTemplates#_app 2.98 0.047 0.047 0.000 0.000 6 <Class::Dir>#[] 2.52 0.042 0.040 0.001 0.001 74 <Module::ActiveSupport::Multibyte> 2.36 0.040 0.037 0.000 0.002 1095 Mustache::Parser#regexp 2.08 0.051 0.033 0.000 0.018 46 <Module::Marshal>#load 1.99 0.032 0.032 0.000 0.000 6 Kernel#require 1.98 0.032 0.032 0.000 0.000 2181 String#to_s 1.67 0.506 0.027 0.000 0.480 1007 *Array#each 1.55 0.050 0.025 0.000 0.025 972 Psych::ScalarScanner#tokenize 1.48 0.024 0.024 0.000 0.000 168 <Class::File>#exist? 1.35 0.068 0.021 0.000 0.046 663 Mustache::Parser#position 1.31 0.066 0.021 0.000 0.045 675 Mustache::Parser#scan_text
34. Profile of our code %self total self wait child calls name 5.41 0.271 0.086 0.000 0.185 675 Mustache::Parser#scan_tags 3.90 0.062 0.062 0.000 0.000 36 BasicObject#instance_eval 3.34 1.031 0.053 0.000 0.978 1 ActionView::CompiledTemplates#_app 2.98 0.047 0.047 0.000 0.000 6 <Class::Dir>#[] 2.52 0.042 0.040 0.001 0.001 74 <Module::ActiveSupport::Multibyte> 2.36 0.040 0.037 0.000 0.002 1095 Mustache::Parser#regexp 2.08 0.051 0.033 0.000 0.018 46 <Module::Marshal>#load 1.99 0.032 0.032 0.000 0.000 6 Kernel#require 1.98 0.032 0.032 0.000 0.000 2181 String#to_s 1.67 0.506 0.027 0.000 0.480 1007 *Array#each 1.55 0.050 0.025 0.000 0.025 972 Psych::ScalarScanner#tokenize 1.48 0.024 0.024 0.000 0.000 168 <Class::File>#exist? 1.35 0.068 0.021 0.000 0.046 663 Mustache::Parser#position 1.31 0.066 0.021 0.000 0.045 675 Mustache::Parser#scan_text  Method name   Time   Calls 
35. Profile of our code %self total self wait child calls name 5.41 0.271 0.086 0.000 0.185 675 Mustache::Parser#scan_tags 3.90 0.062 0.062 0.000 0.000 36 BasicObject#instance_eval 3.34 1.031 0.053 0.000 0.978 1 ActionView::CompiledTemplates#_app 2.98 0.047 0.047 0.000 0.000 6 <Class::Dir>#[] 2.52 0.042 0.040 0.001 0.001 74 <Module::ActiveSupport::Multibyte> 2.36 0.040 0.037 0.000 0.002 1095 Mustache::Parser#regexp 2.08 0.051 0.033 0.000 0.018 46 <Module::Marshal>#load 1.99 0.032 0.032 0.000 0.000 6 Kernel#require 1.98 0.032 0.032 0.000 0.000 2181 String#to_s 1.67 0.506 0.027 0.000 0.480 1007 *Array#each 1.55 0.050 0.025 0.000 0.025 972 Psych::ScalarScanner#tokenize 1.48 0.024 0.024 0.000 0.000 168 <Class::File>#exist? 1.35 0.068 0.021 0.000 0.046 663 Mustache::Parser#position 1.31 0.066 0.021 0.000 0.045 675 Mustache::Parser#scan_text
36. Before and after self calls name self calls name 0.051 2 BasicObject#instance_eva 0.086 675 Mustache::Parser#scan_ta 0.042 6 <Class::Dir>#[] 0.062 36 BasicObject#instance_eva 0.014 110 Mustache::Parser#scan_ta 0.053 1 ActionView::CompiledTemp 0.014 337 *Array#each 0.047 6 <Class::Dir>#[] 0.004 145 Sprockets::Asset#depende 0.040 74 <Module::ActiveSupport:: 0.004 149 *Array#map 0.037 1095 Mustache::Parser#regexp 0.003 110 Mustache::Parser#scan_te 0.033 46 <Module::Marshal>#load 0.003 109 Mustache::Parser#positio 0.032 6 Kernel#require 0.003 110 Mustache::Parser#scan_un 0.032 2181 String#to_s 0.002 2 <Class::IO>#binread 0.027 1007 *Array#each 0.002 186 <Class::File>#exist? 0.025 972 Psych::ScalarScanner#tok 0.002 774 Kernel#is_a? 0.024 168 <Class::File>#exist? 0.002 186 Hike::Trail#stat 0.021 663 Mustache::Parser#positio 0.002 232 String#split 0.021 675 Mustache::Parser#scan_te
37. compiling templates is slow and partials are compiled before each use
38. Recursion
39. Our results page has a list within a list
40. This is broken This is OK
41. - Iteration - Repetition - Recursion
42. - Iteration - Repetition - Recursion
43. Repetition
44. Repetition
45. This is fast but ghastly
46. - Iteration - Repetition ?? - Recursion
47. Recursion is a bit of a dick move
48. Recursion: Use responsibly
49. _results.mustache: {{#results}} {{#is_multiple_results}} <ol class= >{{>_results}}</ol> {{/is_multiple_results}} {{^is_multiple_results}} <li> result code goes here </li> {{/is_multiple_results}} {{/results}}
50. _results.mustache: {{#results}} {{#is_multiple_results}} <ol class= >{{>_results}}</ol> /*Call self*/ {{/is_multiple_results}} {{^is_multiple_results}} <li> result code goes here </li> {{/is_multiple_results}} {{/results}}
51. The problem with this is it’s non-obvious
52. - Iteration - Repetition ?? - Recursion ??
54. Reader, we chose the recursion.
55. Fixing the gem
56. Fixing the gem was the right thing to do
57. Fixing the gem prevents trouble in the future
58. Looking for prior art
59. The fix
60. We added a benchmark instead of a test
61. Writing the pull request https://github.com/mustache/mustache/pull/205
62. Explain the problem
63. Explain the change
64. Be proactive about objections
65. Keep nudging for progress
66. Over half our effort went on getting the change accepted
67. OK thanks bye
68. Links
69. Questions?