Closed Bug 674304 Opened 14 years ago Closed 13 years ago

[performance] Profile questions.views.questions

Categories

(support.mozilla.org :: Code Quality, task, P2)

Product:
support.mozilla.org
Component:
Code Quality
Type:
task

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
2012.11

People

(Reporter: jsocol, Assigned: rrosario)

References

Details

(Whiteboard: u=user c=questions p=1)

Graphite is telling us that questions.views.questions is taking around 800ms on average (wide StdDev). We cache a lot of content there, so we should profile this to see where we can improve it.
Target Milestone: 2011Q3 → 2012Q1
Blocks: 695390
I just watched Michael's latest "What's up with SUMO?" video and OUCH! http://blog.mozilla.com/sumo/2011/11/11/whats-up-with-sumo-nov-11/ Upping the priority of this because OW.
Target Milestone: 2012Q1 → 2011Q4
4 months ago when I filed this, the mean was around 800ms. It started this week closer to 1200 and after the tag filtering was announced in the video (at least the change seems to correlate) it's well north of 1200ms. That is unacceptable on any number of levels.
Below is some data I collected using RunProfileServer (which uses hotshot). The warm cache case is acceptably fast for me locally. As expected, most of the cold cache time is spent doing db queries and parsing wiki->html. Something is telling me our cache isn't working quite as expected in prod or just the frequency of changes in prod is invalidating cache too much? ========== COLD CACHE ========== 88750 function calls (84282 primitive calls) in 2.923 CPU seconds Ordered by: internal time, call count List reduced from 961 to 10 due to restriction <10> ncalls tottime percall cumtime percall filename:lineno(function) 47 2.595 0.055 2.597 0.055 MySQLdb/cursors.py:278(_do_query) 40 0.069 0.002 0.069 0.002 html5lib/src/html5lib/html5parser.py:2438(__init__) 1360 0.011 0.000 0.011 0.000 html5lib/src/html5lib/utils.py:21(__init__) 2375/380 0.007 0.000 0.016 0.000 python2.6/copy.py:144(deepcopy) 82 0.006 0.000 0.006 0.000 python-memcached/memcache.py:1034(readline) 47 0.006 0.000 0.006 0.000 django/django/db/backends/mysql/base.py:288(_valid_connection) 20 0.005 0.000 0.028 0.001 py-wikimarkup/wikimarkup/parser.py:1500(doBlockLevels) 440/20 0.005 0.000 0.007 0.000 python2.6/sre_compile.py:38(_compile) 420/20 0.004 0.000 0.011 0.001 python2.6/sre_parse.py:385(_parse) 2319 0.004 0.000 0.004 0.000 jinja2/_markupsafe/__init__.py:67(__new__) ========== WARM CACHE ========== 47214 function calls (44236 primitive calls) in 0.137 CPU seconds Ordered by: internal time, call count List reduced from 720 to 10 due to restriction <10> ncalls tottime percall cumtime percall filename:lineno(function) 42 0.010 0.000 0.011 0.000 MySQLdb/cursors.py:278(_do_query) 2253/352 0.007 0.000 0.015 0.000 python2.6/copy.py:144(deepcopy) 2319 0.004 0.000 0.004 0.000 jinja2/_markupsafe/__init__.py:67(__new__) 818 0.003 0.000 0.004 0.000 jinja2/_markupsafe/_native.py:14(escape) 54 0.003 0.000 0.003 0.000 python-memcached/memcache.py:1034(readline) 42 0.003 0.000 0.003 0.000 django/django/db/backends/mysql/base.py:288(_valid_connection) 368 0.003 0.000 0.115 0.000 kitsune/apps/questions/templates/questions/questions.html:38(block_content) 2009 0.002 0.000 0.002 0.000 python2.6/copy.py:261(_keep_alive) 157 0.002 0.000 0.003 0.000 django/django/core/urlresolvers.py:305(reverse) 129 0.002 0.000 0.011 0.000 /Users/rlr/dev/kitsune/apps/sumo/helpers.py:59(urlparams)
I landed three commits that reduce queries, caches tags for each question and caches a contributor list for each question. https://github.com/mozilla/kitsune/compare/09fbcfb31d...86097a9fe8 I guess we will find out how this improves the perf graphs when it gets to prod.
Target Milestone: 2011Q4 → ---
This is part of our Q2 goals.
Assignee: james → nobody
Target Milestone: --- → 2012.11
Priority: -- → P2
Summary: Profile questions.views.questions → [performance] Profile questions.views.questions
Assignee: nobody → rrosario
I added a few statsd timers: https://github.com/mozilla/kitsune/commit/f0f0e79852a265b4c4d3b06f2740fff2a99ec4ca This should give me the data to determine what to focus on profiling and optimizing.
The timers added showed that most of the time is spent doing the questions list query. The second most time is stuff that happens within `render` which includes calls to helpers and model properties that may trigger more queries. I left those two timers in and changed the timer name for the query time to be able to distinguish between the filters (unsolved, solved, no-replies, etc) being applied. https://github.com/mozilla/kitsune/commit/faec2f8e1202b773bddb348a34934f8c99b52582 The graph: https://graphite-phx.mozilla.org/render/?target=stats.timers.sumo.questions.view.paginate.*.upper_90&target=stats.timers.sumo.view.questions.views.questions.GET.upper_90&title=questions+view+performance+stuff&id=0283f5f3-aa41-a749-27f4-754acea134a6&width=960&height=600&t=0.9334423278678167&hideLegend=false&from=-1hour Let's wait and see what that tells us. I'll leave this bug open for now until we file a followup.
Filed Bug 765705
Status: NEW → RESOLVED
Closed: 13 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.