1279839 - Fix slow queries in "Recent Docs Activity" on user profiles to mitigate potential DOS

Status: RESOLVED FIXED

(developer.mozilla.org Graveyard :: Profiles, defect)

Description

[Josh Mize [:jgmize]]

What feature should be changed? Please provide the URL of the feature if possible.
==================================================================================
An example of a working profile can be seen on https://developer.mozilla.org/en-US/profiles/jgmize

An example of a user profile page that will not currently render is at /en-US/profiles/Mgjbot but I'm not linking that and please don't visit it until this issue is resolved due to site impact (see below).

What problems would this solve?
===============================
The queries used to generate this section of the profile are extremely inefficient and cause performance and availability problems for profiles of users with many changes. Some profiles will never load at all, and the attempt to load them can cause performance and availability problems for the entire site. Simply visiting select profiles repeatedly at a relatively low frequency is an effective DOS attack against MDN.

Who would use this?
===================
No one, once it is removed.

What would users see?
=====================
A profile without the aforementioned section.

What would users do? What would happen as a result?
===================================================
Users would need to check their browser history or other data sources for their own page edits, and could view the revision history on a per-page history, but would not be able to easily see the activity of other users.

Is there anything else we should know?
======================================

Comment 1

[Josh Mize [:jgmize]]

Attachment: kuma PR 3889

Comment 2

[April King [:April]]

I love it when people report bugs and then assign it to themselves.  :)

Comment 4

[John Whitlock [:jwhitlock]]

The problem has been disabled for non-admins by banning the user. Site staff may still trigger the issue. (so please do not visit)

Similar behavior is seen on https://developer.allizom.org/en-US/profiles/Mgjbot , without hurting production, and without blocking other connections to the staging server. A similar slow query happens on the revision dashboard when searching for the user "Mgjbot", and is still live on the site.

This profile is viewed 1-5 times an hour, and has been for the last few years, mostly by scrapers, and has not been associated with downtime until recently.

There are no recent code changes for this page or query, but there have been some server changes. More research is needed to determine if there is a problem with these server changes.

The first is an increase in servers and database clients. The number of web servers has been doubled to six. An additional async celery server has been added (now 4), and the number of async workers on each server doubled (4 to 8), so an increase of 12 workers to 32.  This is an increase of simultaneous connections to the database.

The second change is the addition of a read-only database server.

Sherri, can you check if the recent server changes have caused issues that show up in the database logs or metrics?

Comment 5

[John Whitlock [:jwhitlock]]

Further info on the user: https://developer.mozilla.org/en-US/docs/User:Mgjbot  The user was last active in 2012, and has roughly 10,000 edits. Sheppy has over 40,000 edits, but his page doesn't show this issue. It appears to be the rare combination of a lot of edits many years ago that triggers this issue.

Comment 6

[John Whitlock [:jwhitlock]]

On my local dev box, I ran some tests, and have more information.

The Mgjbot query takes 28 seconds. There are several users that take more than 1 second:

33.0: Anonymous     13934 edits, last edit 2012-07-05 09:25:03
31.3: Jürgen Jena    2098 edits, last edit 2012-07-11 03:05:12
30.9: Dria           7910 edits, last edit 2012-06-11 10:29:20
28.2: Mgjbot        10390 edits, last edit 2012-07-13 17:32:10
16.9: Fredchat       2258 edits, last edit 2014-11-03 01:49:16
15.7: kscarfone      5167 edits, last edit 2015-06-06 13:12:26
14.0: lmorchard      5883 edits, last edit 2014-08-07 08:14:41
13.6: ethertank     23238 edits, last edit 2015-02-12 07:54:04
10.3: Jorend         3951 edits, last edit 2013-12-19 14:27:33
 8.5: Sevenspade     2118 edits, last edit 2016-02-08 16:05:18
 6.6: Ptak82        11969 edits, last edit 2014-11-19 17:50:27
 5.5: BenoitL        3273 edits, last edit 2015-04-26 06:45:01
 5.2: caxadevidi     2353 edits, last edit 2015-06-11 20:54:20
 5.2: tregagnon      3141 edits, last edit 2016-03-04 01:20:41
 5.0: trevor         6242 edits, last edit 2016-01-29 16:50:35
 5.0: FredB          2547 edits, last edit 2015-04-25 14:13:08
 4.1: kohei.yoshino  3033 edits, last edit 2015-11-10 21:45:54
 3.9: xiwoxaj       10381 edits, last edit 2015-07-21 22:01:44
 3.7: ranad          8910 edits, last edit 2015-07-22 22:05:12
 3.0: marks          4093 edits, last edit 2016-04-24 20:23:29
 1.2: Jeremie        6971 edits, last edit 2016-04-09 04:31:27

So,
1. It's not one user. It's just Mgjbot was likely to be hit by scrapers.
2. It's bad on a dev box (30 seconds is too long), but occasionally catastrophic for production
3. It's not a combo of a lot of edits a long time ago - some are recent

Ordering by ID rather than created is 10x faster and has the same results. I'm proposing changing ordering from created to ID on both the user profile and the dashboard.

Comment 7

[Josh Mize [:jgmize]]

(In reply to John Whitlock [:jwhitlock] from comment #6)
> On my local dev box, I ran some tests, and have more information.
> 
> The Mgjbot query takes 28 seconds. There are several users that take more
> than 1 second:
[...]
> 1. It's not one user. It's just Mgjbot was likely to be hit by scrapers.
> 2. It's bad on a dev box (30 seconds is too long), but occasionally
> catastrophic for production
> 3. It's not a combo of a lot of edits a long time ago - some are recent
> 
> Ordering by ID rather than created is 10x faster and has the same results.
> I'm proposing changing ordering from created to ID on both the user profile
> and the dashboard.

Thanks for all your work on this John. That sounds like a plan.

Comment 8

[Sheeri Cabral [:sheeri]]

I think John did the necessary optimization work. Let me know if you need any more. I don't see anything in error logs, let me know if you want me to go to slow query logs. I do best if you can point to specific queries.

Comment 9

[John Whitlock [:jwhitlock]]

Here's the profile page query for Mgjbot:

SELECT `wiki_revision`.`id`, `wiki_revision`.`document_id`, `wiki_revision`.`title`, `wiki_revision`.`slug`, `wiki_revision`.`tidied_content`, `wiki_revision`.`keywords`, `wiki_revision`.`tags`, `wiki_revision`.`toc_depth`, `wiki_revision`.`render_max_age`, `wiki_revision`.`created`, `wiki_revision`.`comment`, `wiki_revision`.`creator_id`, `wiki_revision`.`is_approved`, `wiki_revision`.`based_on_id`, `wiki_revision`.`is_mindtouch_migration` FROM `wiki_revision` WHERE `wiki_revision`.`creator_id` = 19831 ORDER BY `wiki_revision`.`created` DESC LIMIT 5;

And the dashboard query:

SELECT `wiki_revision`.`id`, `wiki_revision`.`document_id`, `wiki_revision`.`title`, `wiki_revision`.`slug`, `wiki_revision`.`summary`, `wiki_revision`.`tidied_content`, `wiki_revision`.`keywords`, `wiki_revision`.`tags`, `wiki_revision`.`toc_depth`, `wiki_revision`.`render_max_age`, `wiki_revision`.`created`, `wiki_revision`.`comment`, `wiki_revision`.`creator_id`, `wiki_revision`.`is_approved`, `wiki_revision`.`based_on_id`, `wiki_revision`.`is_mindtouch_migration` FROM `wiki_revision` INNER JOIN `auth_user` ON ( `wiki_revision`.`creator_id` = `auth_user`.`id` ) WHERE `auth_user`.`username` LIKE 'Mgjbot%' ORDER BY `wiki_revision`.`id` DESC LIMIT 50

Comment 10

[John Whitlock [:jwhitlock]]

Code is deployed to production, and Mgjbot unbanned. Views the problematic profiles listed above. In some cases, ID order is not the same as created order, such as https://developer.mozilla.org/en-US/profiles/Jeremie. This is a mystery (why are they ordered in the anonymized database?), and may require further investigation.  The Revision Dashboard appears to be ordered, however, and the profile pages are uniformly fast.

Comment 11

[Josh Mize [:jgmize]]

Thanks John, nice work. Looking at the performance numbers for the user profile page, the huge spikes in response time have completely dropped off since the deployment, so I think we can consider this particular bug resolved. The revisions dashboard query is still very slow, but we can address that in a separate bug.

Comment 12

[April King [:April]]

Nice work on this one!