Addons-server: MaDonna's profile page is hanging

[atsay]

Describe the problem and steps to reproduce it:

Go to https://addons.mozilla.org/en-US/firefox/user/MaDonna/
It takes a long time to load, if at all.

What happened?

It seems to only affect her page and not others on AMO. Possible we've come upon an edge case with her in terms of size of profile page?

What did you expect to happen?

I expected it to load like any other AMO page.

Anything else we should know?

She recently began using HTML in her About Me field. Something to do with that?

[kumar303]

I experienced this too.

If it's not related to the HTML, it could be database related.

@bqbn could we look at the slow query logs for clues? This user develops an incredible amount of themes so her profile page may be causing a slow query.

[bqbn]

I haven't found any slow queries related to this user. However, Kibana does show an error:

Internal Server Error: /en-US/firefox/user/MaDonna/ :/usr/lib/python2.7/site-packages/django/core/handlers/base.py:256
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 132, in get_response
response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/data/olympia/src/olympia/users/views.py", line 58, in wrapper
return f(request, user, *args, **kw)
File "/data/olympia/src/olympia/users/views.py", line 266, in profile
return render(request, 'users/profile.html', data)
File "/data/olympia/src/olympia/amo/utils.py", line 78, in render
rendered = render_to_string(request, template, ctx)
File "/data/olympia/src/olympia/amo/utils.py", line 74, in render_to_string
return template.render(get_context())
File "/usr/lib/python2.7/site-packages/jingo/__init__.py", line 103, in render
return super(Template, self).render(context_dict)
File "/usr/lib/python2.7/site-packages/jinja2/environment.py", line 989, in render
return self.environment.handle_exception(exc_info, True)
File "/usr/lib/python2.7/site-packages/jinja2/environment.py", line 754, in handle_exception
reraise(exc_type, exc_value, tb)
File "/data/olympia/src/olympia/users/templates/users/profile.html", line 1, in top-level template code
{% extends "impala/base_shared.html" %}
File "/data/olympia/src/olympia/../../src/olympia/templates/impala/base_shared.html", line 1, in top-level template code
{% extends 'impala/base.html' %}
File "/data/olympia/src/olympia/../../src/olympia/templates/impala/base.html", line 163, in top-level template code
{% block main_content %}
File "/data/olympia/src/olympia/../../src/olympia/templates/impala/base.html", line 166, in block "main_content"
{% block content %}{% endblock %}
File "/data/olympia/src/olympia/users/templates/users/profile.html", line 95, in block "content"
{% if reviews %}
File "/usr/lib/python2.7/site-packages/django/core/paginator.py", line 117, in __len__
return len(self.object_list)
File "/usr/lib/python2.7/site-packages/django/db/models/query.py", line 144, in __len__
self._fetch_all()
File "/usr/lib/python2.7/site-packages/django/db/models/query.py", line 965, in _fetch_all
self._result_cache = list(self.iterator())
File "/data/olympia/src/django-cache-machine/caching/base.py", line 113, in __iter__
obj = next(iterator)
File "/data/olympia/src/django-cache-machine/caching/base.py", line 202, in fetch_by_id
cache.set_many(new)
File "/usr/lib/python2.7/site-packages/django/core/cache/backends/memcached.py", line 154, in set_many
self._cache.set_multi(safe_data, self.get_backend_timeout(timeout))
File "/usr/lib/python2.7/site-packages/memcache.py", line 725, in set_multi
min_compress_len)
File "/usr/lib/python2.7/site-packages/memcache.py", line 782, in _val_to_store_info
pickler.dump(val)#012PicklingError: Can't pickle <type 'function'>: attribute lookup __builtin__.function failed

[eviljeff]

Seems to happening when fetching the list of reviews she's written, rather than the themes she's developed.

[eviljeff]

@bqbn you mean sentry? I had a look in Kibana and couldn't see much (though it's hard to see much unless you know which log entry you're looking for)

[eviljeff]

According to https://addons.mozilla.org/api/v3/reviews/review/?user=6199839 she's written 5573 reviews (many of them in reply to other user's reviews, seemingly) so that's possibly choking something.

[bqbn]

@eviljeff I mean Kibana in logging 1.0. But yeah, Sentry seems to have it too.

[muffinresearch]

Related sentry links here: https://sentry.prod.mozaws.net/operations/olympia-prod/issues/604935/ and here: https://sentry.prod.mozaws.net/operations/olympia-prod/issues/604894/

[eviljeff]

@EnTeQuAk suggests changing the {% if reviews %} in the template may be enough (it causes the whole queryset to be evaluated).
Alternatively could do {{ for ... }} .. {{ else }} ... {{ endfor }}

[muffinresearch]

@eviljeff could you take a look at running up a patch for this next week?

[kumar303]

The site is still running out of memory, possibly due to this URL. From IRC after the deploy:

12:57 jason: so I am pretty sure it's https://addons.mozilla.org/en-US/android/user/MaDonna/ that is causing the OOM, but I am trying to get more concrete evidence

The page still loads slowly (and in a broken state) for me so I'm going to re-open the bug.

[diox]

The removal of the {% if reviews %} should not have changed much:

• It's paginated (the view does reviews = amo.utils.paginate(request, user.reviews.all())), so the query would be limited (20 items is the default)
• The query is only executed once, since it's the same variable, django queryset caching would prevent the query from being executed a second time
• The page is doing the same thing with other queries anyway, like personas. Though all of them do seem to be paginated properly.

[bqbn]

We verified, on one of the production instances, by running

curl -D- -H Host: addons.mozilla.org http://localhost:9000/en-US/android/user/MaDonna/ -so/dev/null

could reproduce the oom kill.

One curl command could cause a uwsgi process uses as much as 4GB memory before the process is finally oom-killed.

[diox]

Found it.

Post mortem on how I discovered it, because that was not trivial:

Newrelic was helpful to pinpoint the issue : from slowest transactions, it linked me the profile page mentioned in this issue, and provided details on what happened in specific instances of this problem. It showed that rendering vcard.html was super slow, and the slowness was caused by calling Memcached get_multi. It also shown that a limitedless database query was being made to fetch all public add-ons...

At this point I noticed that the num_addons_listed query was suspiciously similar, except it did a COUNT(*) which we would not see... We reproduced the problem with the API as well with @jasonthomas , further reducing the scope.

I looked at the code more closely. num_addons_listed is a @property, which simply calls self.addons_listed.count(); addons_listed is a @cached_property returning the queryset matching the offending query... Here is the thing: before doing the count(), that cached property is evaluated in order to cache it... Evaluating the full queryset. MaDonna has 16136 themes, causing everything to blow up as we fetched and try to cache into memcache those 16136 objects... Note that this only happens with our own implementation of @cached_property, not django's.

I'll provide a patch soon.

[EnTeQuAk]

This apparently is still occouring: https://sentry.prod.mozaws.net/operations/olympia-prod/issues/604935/

[eviljeff]

https://github.com/mozilla/addons-server/releases/tag/2017.06.01-2 isn't on prod yet (apparently)

[diox]

It will be deployed on prod today, it was too late yesterday because there were issues with the deploy itself.

[EnTeQuAk]

Heh, I didn't read backlog correctly. Sorry for the misunderstanding :)

[kumar303]

We're deploying it today at 9:30 Pacific

[atsay]

Thanks everyone for fixing this!

[SVSanta]

Verified as fixed using AMO-prodFF55(Win 10 64Bit).
Postfix video: