Fixing a performance issue with the mustache gem

Transcript

1. 1.

   fixing a performance issue with the mustache gem (a bit

   less boring than it sounds)
2. 2.

   @alicebartlett & @evilstreak

3. 3.

   We used to work at GDS, on gov.uk

4. 4.

   In this talk: - Adding a feature - Finding a

   bug - working around the bug - fixing the bug
5. 5.

   GOV.uk is the best place to find government services and

   information
6. 6.

   These are Manuals They are multi- page long form documents

7. 7.

   New feature: search within a manual

8. 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. 9.

   From this:

10. 10.

    To this: From this:

11. 11.

    None
12. 12.

    Search pages use mustache (specifically: the ruby implementation of mustache

    via the mustache gem)
13. 13.

    From this:

14. 14.

    To this: From this:

15. 15.

    To this: then from this:

16. 16.

    This is very uninteresting.

17. 17.

    Using partials in this way is in the docs: from:

    https://mustache.github.io/mustache.5.html#Partials
18. 18.

    full PR is here: https://github.com/alphagov/frontend/pull/784

19. 19.

    Time to deploy!

20. 20.

    This should have been straightforward

21. 21.

    None
22. 22.

    -

23. 23.

    -

24. 24.

    We deploy to staging

25. 25.

    We proceed to production

26. 26.

    Slowly, shit hits the fan.

27. 27.

    -

28. 28.

    We rollback and investigate on staging

29. 29.

    Breaking things isn’t bad if you have a good plan

    to recover
30. 30.

    Profiling

31. 31.

    We found out the problem was this CPU spike

32. 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. 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. 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. 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. 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. 37.

    compiling templates is slow and partials are compiled before each

    use
38. 38.

    Recursion

39. 39.

    Our results page has a list within a list

40. 40.

    This is broken This is OK

41. 41.

    - Iteration - Repetition - Recursion

42. 42.

    - Iteration - Repetition - Recursion

43. 43.

    Repetition

44. 44.

    Repetition

45. 45.

    This is fast but ghastly

46. 46.

    - Iteration - Repetition ?? - Recursion

47. 47.

    Recursion is a bit of a dick move

48. 48.

    Recursion: Use responsibly

49. 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. 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. 51.

    The problem with this is it’s non-obvious

52. 52.

    - Iteration - Repetition ?? - Recursion ??

53. 53.

    None
54. 54.

    Reader, we chose the recursion.

55. 55.

    Fixing the gem

56. 56.

    Fixing the gem was the right thing to do

57. 57.

    Fixing the gem prevents trouble in the future

58. 58.

    Looking for prior art

59. 59.

    The fix

60. 60.

    We added a benchmark instead of a test

61. 61.

    Writing the pull request https://github.com/mustache/mustache/pull/205

62. 62.

    Explain the problem

63. 63.

    Explain the change

64. 64.

    Be proactive about objections

65. 65.

    Keep nudging for progress

66. 66.

    Over half our effort went on getting the change accepted

67. 67.

    OK thanks bye

68. 68.

    Links

69. 69.

    Questions?