@alicebartlett and I gave this talk at LRUG, on Monday 12th October 2015.
fixing a performance issue withthe mustache gem(a bit less boring than it sounds)
View Slide
@alicebartlett&@evilstreak
We used to work atGDS, on gov.uk
In this talk:- Adding a feature- Finding a bug- working around the bug- fixing the bug
GOV.uk is the best placeto find governmentservices andinformation
These are ManualsThey are multi-page long formdocuments
New feature:search within a manual
This is search withina manualA list of resultsfrom a Manual with anested list ofresults from therest of GOV.UK
From this:
To this:From this:
Search pages use mustache(specifically: the ruby implementation of mustache via themustache gem)
To this:then from this:
This is veryuninteresting.
Using partials in this way is in the docs:from: https://mustache.github.io/mustache.5.html#Partials
full PR is here:https://github.com/alphagov/frontend/pull/784
Time to deploy!
This should have beenstraightforward
-
We deploy tostaging
We proceed toproduction
Slowly, shit hits thefan.
We rollback andinvestigate on staging
Breaking things isn’t badif you have a good plan torecover
Profiling
We found out the problemwas this CPU spike
# Profile the codeRubyProf.start...[code to profile]...result = RubyProf.stop# Print a flat profile to textprinter = RubyProf::FlatPrinter.new(result)printer.print(STDOUT)Measuring code with ruby-prof is easy
Profile of our code%self total self wait child calls name5.41 0.271 0.086 0.000 0.185 675 Mustache::Parser#scan_tags3.90 0.062 0.062 0.000 0.000 36 BasicObject#instance_eval3.34 1.031 0.053 0.000 0.978 1 ActionView::CompiledTemplates#_app2.98 0.047 0.047 0.000 0.000 6 #[]2.52 0.042 0.040 0.001 0.001 74 2.36 0.040 0.037 0.000 0.002 1095 Mustache::Parser#regexp2.08 0.051 0.033 0.000 0.018 46 #load1.99 0.032 0.032 0.000 0.000 6 Kernel#require1.98 0.032 0.032 0.000 0.000 2181 String#to_s1.67 0.506 0.027 0.000 0.480 1007 *Array#each1.55 0.050 0.025 0.000 0.025 972 Psych::ScalarScanner#tokenize1.48 0.024 0.024 0.000 0.000 168 #exist?1.35 0.068 0.021 0.000 0.046 663 Mustache::Parser#position1.31 0.066 0.021 0.000 0.045 675 Mustache::Parser#scan_text
Profile of our code%self total self wait child calls name5.41 0.271 0.086 0.000 0.185 675 Mustache::Parser#scan_tags3.90 0.062 0.062 0.000 0.000 36 BasicObject#instance_eval3.34 1.031 0.053 0.000 0.978 1 ActionView::CompiledTemplates#_app2.98 0.047 0.047 0.000 0.000 6 #[]2.52 0.042 0.040 0.001 0.001 74 2.36 0.040 0.037 0.000 0.002 1095 Mustache::Parser#regexp2.08 0.051 0.033 0.000 0.018 46 #load1.99 0.032 0.032 0.000 0.000 6 Kernel#require1.98 0.032 0.032 0.000 0.000 2181 String#to_s1.67 0.506 0.027 0.000 0.480 1007 *Array#each1.55 0.050 0.025 0.000 0.025 972 Psych::ScalarScanner#tokenize1.48 0.024 0.024 0.000 0.000 168 #exist?1.35 0.068 0.021 0.000 0.046 663 Mustache::Parser#position1.31 0.066 0.021 0.000 0.045 675 Mustache::Parser#scan_text Method name Time Calls
Before and afterself calls name self calls name0.051 2 BasicObject#instance_eva 0.086 675 Mustache::Parser#scan_ta0.042 6 #[] 0.062 36 BasicObject#instance_eva0.014 110 Mustache::Parser#scan_ta 0.053 1 ActionView::CompiledTemp0.014 337 *Array#each 0.047 6 #[]0.004 145 Sprockets::Asset#depende 0.040 74 0.004 149 *Array#map 0.037 1095 Mustache::Parser#regexp0.003 110 Mustache::Parser#scan_te 0.033 46 #load0.003 109 Mustache::Parser#positio 0.032 6 Kernel#require0.003 110 Mustache::Parser#scan_un 0.032 2181 String#to_s0.002 2 #binread 0.027 1007 *Array#each0.002 186 #exist? 0.025 972 Psych::ScalarScanner#tok0.002 774 Kernel#is_a? 0.024 168 #exist?0.002 186 Hike::Trail#stat 0.021 663 Mustache::Parser#positio0.002 232 String#split 0.021 675 Mustache::Parser#scan_te
compiling templates is slowand partials are compiledbefore each use
Recursion
Our results page hasa list within a list
This is brokenThis is OK
- Iteration- Repetition- Recursion
Repetition
This is fast butghastly
- Iteration- Repetition ??- Recursion
Recursion is a bit of adick move
Recursion: Use responsibly
_results.mustache:{{#results}}{{#is_multiple_results}}{{>_results}}{{/is_multiple_results}}{{^is_multiple_results}} result code goes here {{/is_multiple_results}}{{/results}}
_results.mustache:{{#results}}{{#is_multiple_results}}{{>_results}} /*Call self*/{{/is_multiple_results}}{{^is_multiple_results}} result code goes here {{/is_multiple_results}}{{/results}}
The problem with thisis it’s non-obvious
- Iteration- Repetition ??- Recursion ??
Reader, we chose therecursion.
Fixing the gem
Fixing the gem was theright thing to do
Fixing the gem preventstrouble in the future
Looking for prior art
The fix
We added a benchmarkinstead of a test
Writing the pull requesthttps://github.com/mustache/mustache/pull/205
Explain the problem
Explain the change
Be proactive aboutobjections
Keep nudgingfor progress
Over half our effortwent on getting thechange accepted
OK thanks bye
Links
Questions?
rmatsuoka
pospome
.png){kind=avatar}
melonattacker
tomokusaba
rakus_dev
ostk0069
takefumiyoshii
kasacchiful
gregonnet
philipschwarz
blueswen
atinfinity
mojombo
smashingmag
destraynor
yeseniaperezcruz
malarkey
addyosmani
sachag
tanoku
danielanewman
jasonvnalue
stephaniewalter
reverentgeek