Pro Yearly is on sale from $80 to $50! »

Fixing a performance issue with the mustache gem

Fixing a performance issue with the mustache gem

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

76b802165c7c55b9c719495d5e4dbf48?s=128

Dominic Baggott

October 12, 2015
Tweet

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:

  11. None
  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

  21. None
  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 ??

  53. None
  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?