Page MenuHomePhabricator
Create Task
Maniphest T225774

[Timebox: 8 hours] Database reports tool experiencing SQL timeouts
Closed, ResolvedPublicSpike
Actions

Description

The Database Reports tool has been spitting a lot of SQL timeouts into its error log. It's not clear if this started happening more before or after the actor timeout.

We should probably take this opportunity to add timestamps to the error log so we'll have that information next time.

This is the existing error:

Traceback (most recent call last):
  File "/data/project/database-reports/reports/database-reports/main.py", line 82, in <module>
    main(sys.argv)
  File "/data/project/database-reports/reports/database-reports/main.py", line 25, in main
    method()
  File "/data/project/database-reports/reports/database-reports/main.py", line 46, in pages_with_most_revisions
    self.rep.pages_with_most_revisions()
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/reports.py", line 92, in pages_with_most_revisions
    cur.execute( query )
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 170, in execute
    result = self._query(query)
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 328, in _query
    conn.query(q)
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 517, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 732, in _read_query_result
    result.read()
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1075, in read
    first_packet = self.connection._read_packet()
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 657, in _read_packet
    packet_header = self._read_bytes(4)
  File "/mnt/nfs/labstore-secondary-tools-project/database-reports/reports/database-reports/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 707, in _read_bytes
    CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')

Related Objects

Event Timeline

MaxSem created this task.Jun 14 2019, 2:45 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 14 2019, 2:45 AM
MaxSem mentioned this in T219324: Update tools maintained by Community-Tech to use new actor storage.Jun 14 2019, 2:55 AM
Niharika moved this task from New & TBD Tickets to Needs Discussion on the Community-Tech board.Jun 19 2019, 6:32 PM
Niharika subscribed.

@MaxSem Can you quantify "a lot"? How often and which report(s)? That will help me prioritise this.

MaxSem added a comment.Jul 2 2019, 11:08 PM

Can't tell because logs don't have timestamps, but the error log is pretty large.

• aezell renamed this task from Database reports SQL timeouts to Database reports tool experiencing SQL timeouts.Jul 9 2019, 11:20 PM
• aezell updated the task description. (Show Details)
Niharika renamed this task from Database reports tool experiencing SQL timeouts to [Timebox: 8 hours] Database reports tool experiencing SQL timeouts.Jul 9 2019, 11:21 PM
Niharika changed the subtype of this task from "Task" to "Spike".
Niharika moved this task from Needs Discussion to Up Next (June 3-21) on the Community-Tech board.Jul 9 2019, 11:31 PM
MusikAnimal subscribed.EditedJul 9 2019, 11:51 PM

The query that is timing out is at https://github.com/wikimedia/database-reports/blob/a901b301a29652c39a20eab971990ba87df479ba/reports.py#L102-L106

To simplify, let's take out the JOIN on page (which isn't slowing it down):

SELECT COUNT(*) AS revisions, rev_page
FROM revision
GROUP BY rev_page
ORDER BY revisions DESC
LIMIT 1000

The query plan is pretty awful. I'm not sure how you could break this out into separate queries.

• aezell subscribed.Jul 10 2019, 1:20 PM

It's the GROUP BY that causes the query plan to do a filesort which is the problem as the optimizer tool tells us. I think the COUNT(*) AS revisions makes this use a temporary column and the GROUP BY is on that column. As far as I know, an index can't help that problem though the query is making use of the rev_page index apparently.

We can eliminate that filesort by using an ORDER BY NULL instead of ORDER BY revisions DESC. We could sort the resultset in code at that point. But, then, we're faced with possibly not getting all the data that we want as long as that LIMIT is there.

In testing this, the implied sorting by the GROUP BY isn't enough because the resultset is too large even at the LIMIT 1000. A LIMIT 10000 takes nearly a minute to complete on the replicas and it still doesn't reliably give you all the rows at the top end.

In short, I don't know that there's a way to avoid the filesort for this kind of query with the current schema. To answer this query, we have to scan all the rows in the table and even with an index, it's just a lot of rows at over 700 million according to the EXPLAIN.

MaxSem mentioned this in T228344: Add timestamps to Database Reports error output.Jul 17 2019, 9:21 PM
ifried moved this task from Up Next (June 3-21) to Kanban (Q1 2019-20) on the Community-Tech board.Aug 27 2019, 3:44 PM
ifried edited projects, added Community-Tech (Kanban (Q1 2019-20)); removed Community-Tech.
MusikAnimal assigned this task to • aezell.Oct 1 2019, 10:22 PM
MusikAnimal moved this task from Ready to Needs Review/Feedback on the Community-Tech (Kanban (Q1 2019-20)) board.

I'm going to go ahead and move to Needs Review. I think T225774#5319960 and T225774#5320840 summarize the issue. Basically there doesn't appear to be a workable solution. This query was always really slow, and apparently we're at the point where there are so many revisions that it just won't finish. I suggest we retire the "Pages with most revisions" database report.

• aezell added a comment.Oct 1 2019, 10:40 PM

Who is the primary audience for these reports? Where do they end up?

Also, you know it's trouble when I'm making proclamations about the EXPLAIN :)

MBinder_WMF edited projects, added Community-Tech (Kanban-Q2-2019-20); removed Community-Tech (Kanban (Q1 2019-20)).Oct 3 2019, 10:20 PM
MBinder_WMF moved this task from Ready to Needs Review/Feedback on the Community-Tech (Kanban-Q2-2019-20) board.Oct 3 2019, 10:40 PM
• aezell closed this task as Resolved.Oct 7 2019, 5:08 PM

Pages with the Most Revisions is the report that fails on occasion. We will leave it in because it does work sometimes and some people get value.

Niharika added a comment.Oct 8 2019, 4:06 AM
In T225774#5539697, @aezell wrote:

Who is the primary audience for these reports? Where do they end up?

Most of them end up here: https://en.wikipedia.org/wiki/Wikipedia:Database_reports such as https://en.wikipedia.org/wiki/Wikipedia:Database_reports/Forgotten_articles.
Not all of these are ours.
The bot also works in a few other languages - posting similar lists on other language wikis.
Primary audience are community members who work off of these as backlogs to improve/fix them as needed.

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits