Looks like there was some heavy load on the server in the ~20 minutes before the OOM:

https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1043&var-network=eth0&from=1485940393438&to=1485942289902

There are some really slow queries running at the time: https://tendril.wikimedia.org/report/slow_queries?host=%5Edb1043&user=&schema=&qmode=eq&query=&hours=1

The replicat (db1048 also crashed at the same time) so I am going to check the binlogs to see what happened at that time.

This is the last insert we got before the crash (of both, master and slave)

INSERT INTO `search_documentfield`
          (phid, phidType, field, auxPHID, corpus, stemmedCorpus) VALUES ('PHID-TASK-wiuz5mmruodmyfo33aqc', 'TASK', 'body', NULL, 'Replace the button\'s name and link from \"Zur Hauptseite des Wikis\" (en: to the main page of the wiki) which leads to the mainpage of Wikimedia Commons with \"Zur Hauptseite von Wikipedia\" (en: to the main page of Wikipedia) which would lead to the mainpage of Wikipedia.', 'replac the button name and link from zur hauptseit des wiki main page wiki which lead mainpag wikimedia common with von wikipedia would lead')
/*!*/;
# at 365290732
#170201  9:39:04 server id 171970592  end_log_pos 365290759     Xid = 6912796981

Both, master, db1043 and slave db1048 crashed, but db2012 didn't crash.

In T156905#2989343, @Volans wrote:

Looks like there was some heavy load on the server in the ~20 minutes before the OOM:

https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1043&var-network=eth0&from=1485940393438&to=1485942289902

However, db1048 (the slave) also crashed and that one is only supposed to have the replication thread running right?
https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1048&var-network=eth0&from=now-3h&to=now

Although there are some selects there too (the rootuser was me):
https://tendril.wikimedia.org/report/slow_queries?host=%5Edb1048&user=&schema=&qmode=eq&query=&hours=2

These search matches the time of the crash on both servers and it was also executed on BOTH servers:

https://tendril.wikimedia.org/report/slow_queries_checksum?checksum=ab39d10e892fa3ec23a56a20ebde12db&host=%5Edb1043&user=&schema=&hours=2
https://tendril.wikimedia.org/report/slow_queries_checksum?checksum=2ac761d7e1455ec309713cce6c827a51&host=%5Edb1048&user=&schema=&hours=2

The SELECT is:

SELECT documentPHID, MAX(fieldScore) AS documentScore FROM (SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore FROM `search_document` document JOIN `search_documentfield` field ON field.phid = document.phid JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open' WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000) query JOIN `search_document` root ON query.documentPHID = root.phid GROUP BY documentPHID ORDER BY documentScore DESC LIMIT 0, 100

On the master it started at 9:21 and as per tendril it took 1029 seconds which is around 17 minutes, that make us to reach: 09:38
The crash happened (as per mysql logs) at 9:39:04 so it looks pretty similar.

If we look at the slave, db1048, the SELECT started at: 09:39:23 and it run for 19 seconds (got killed because the server crashed) and the server crashed at: 09:39:46 which matches the timing too.

@Marostegui hi, it looks like the server is running version Server version: 10.0.23-MariaDB-log

Should we update it to 10.0.29 the package that @jcrespo built?

@Marostegui could it b a memory leak?

could this https://github.com/MariaDB/server/commit/b7dc830 be the fix?

However, db1048 (the slave) also crashed and that one is only supposed to have the replication thread running right?

No, at around 09:39:31, phabricator's proxy, dbproxy1003 failed over to db1048 because it lost contact with its master.

In T156905#2989430, @Paladox wrote:

@Marostegui hi, it looks like the server is running version Server version: 10.0.23-MariaDB-log

Should we update it to 10.0.29 the package that @jcrespo built?

Hi!
I guess we will eventually upgrade it. But in this case I don't think it is related to the FTS indexes. So far it looks like a slow/massive query overloaded the server and make it run out of memory.
Remember that db1048, which also crashed, is running the new version.

The only server that didn't crash was db2012 because it never got that SELECT.

does this mean that phabricator needs improvements to it's query?

In T156905#2989474, @Paladox wrote:

does this mean that phabricator needs improvements to it's query?

I believe so, or at least on that particular query, which made two servers crash pretty much at the same time, specially on db1048 which crashed 20 seconds after starting to process it.

We are evaluating some remedy ideas to prevent this from server side, but these are just temporary and hard patches.
@epriestley do you have any thoughts on this?

Thanks!

Mentioned in SAL (#wikimedia-operations) [2017-02-01T13:21:37Z] <marostegui> Clean up db1043 replication thread (it was replicating from db1048 which looks like an old thing) - T156905

I'm not sure why the query is slow or requires a significant amount of memory. The structure of the query specifically tries to avoid this, by sacrificing result quality to limit the cost of the query, but perhaps the structure of the query can be improved.

Here's the overall problem I have tried to solve with this query:

• If a user queries for a very common term, they may match an extremely large number of results.
• Matching all those results and then ranking them could potentially require a large amount of memory.
• Avoid this by sacrificing result quality: initially match no more than 1,000 results, then rank just those results.

The intent is to give users results quickly when they execute an excessively broad search. The theory is: their search is probably too broad anyway, even if we rank the entire set of documents; and the cost of examining the entire set of documents is potentially very large.

The inner query is:

SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore
  FROM `search_document` document
  JOIN `search_documentfield` field ON field.phid = document.phid
  JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
  WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000

Note that this is a LIMIT 1000 with no ORDER clause. The intent is to let the database select the first 1,000 rows it can find (here: open tasks matching the search terms), without needing to build or sort a large result set. The intent is that if a user queries for search terms with a very large number of matches, we throw away 99% of them immediately in order to keep the working set small.

The outer query just groups and sorts the 1,000 results returned by the inner query.

It would be helpful to understand:

• Is the inner query the problem on its own? When run in isolation, does it execute quickly? What does EXPLAIN look like?
• Is the outer query the problem on its own? If you SELECT the inner query into a temporary table, then run the outer query on it, does it execute quickly? What does EXPLAIN look like?
• Is the combination of the two queries the problem?

More broadly: Assuming the inner query is the issue, why does the inner query take a long time to return? Why does it consume a large amount of memory given that it has LIMIT 1000 with no ORDER clause? (This query may be written in a bad way that I'm just out of my depth on, and I'm not sure what to do in order to try to answer these questions.)

One vague possibility is that you may have a few documents which are extremely large: for example, perhaps someone wrote a 1GB comment on a task somewhere, including the words "translatewiki". We do not currently truncate content when building the search index, so I could imagine that this might explain the large apparent size of the working set. This seems very unlikely to be the issue, but it's the only thing I could immediately think of.

Hey @epriestley - thanks for the fast response!

In T156905#2989711, @epriestley wrote:

I'm not sure why the query is slow or requires a significant amount of memory. The structure of the query specifically tries to avoid this, by sacrificing result quality to limit the cost of the query, but perhaps the structure of the query can be improved.

Here's the overall problem I have tried to solve with this query:

• If a user queries for a very common term, they may match an extremely large number of results.
• Matching all those results and then ranking them could potentially require a large amount of memory.
• Avoid this by sacrificing result quality: initially match no more than 1,000 results, then rank just those results.

The intent is to give users results quickly when they execute an excessively broad search. The theory is: their search is probably too broad anyway, even if we rank the entire set of documents; and the cost of examining the entire set of documents is potentially very large.

The inner query is:

SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore
  FROM `search_document` document
  JOIN `search_documentfield` field ON field.phid = document.phid
  JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
  WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000

Note that this is a LIMIT 1000 with no ORDER clause. The intent is to let the database select the first 1,000 rows it can find (here: open tasks matching the search terms), without needing to build or sort a large result set. The intent is that if a user queries for search terms with a very large number of matches, we throw away 99% of them immediately in order to keep the working set small.

The outer query just groups and sorts the 1,000 results returned by the inner query.

It would be helpful to understand:

• Is the inner query the problem on its own? When run in isolation, does it execute quickly? What does EXPLAIN look like?

The inner query takes QUITEto execute:

root@MISC m3[phabricator_search]>   select @@hostname;
+------------+
| @@hostname |
+------------+
| db1048     |
+------------+
1 row in set (0.00 sec)

SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore
    ->   FROM `search_document` document
    ->   JOIN `search_documentfield` field ON field.phid = document.phid
    ->   JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
    ->   WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000;
5 rows in set (22 min 32.80 sec)

This is the explain:

root@MISC m3[phabricator_search]> explain SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore   FROM `search_document` document   JOIN `search_documentfield` field ON field.phid = document.phid   JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'   WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000;
+------+-------------+----------+----------+------------------+------------+---------+-------------------------------+------+-------------+
| id   | select_type | table    | type     | possible_keys    | key        | key_len | ref                           | rows | Extra       |
+------+-------------+----------+----------+------------------+------------+---------+-------------------------------+------+-------------+
|    1 | SIMPLE      | field    | fulltext | phid,key_corpus  | key_corpus | 0       |                               |    1 | Using where |
|    1 | SIMPLE      | statuses | ref      | phid,relation    | phid       | 66      | phabricator_search.field.phid |    1 | Using where |
|    1 | SIMPLE      | document | eq_ref   | PRIMARY,key_type | PRIMARY    | 66      | phabricator_search.field.phid |    1 | Using where |
+------+-------------+----------+----------+------------------+------------+---------+-------------------------------+------+-------------+
3 rows in set (0.00 sec)

• Is the outer query the problem on its own? If you SELECT the inner query into a temporary table, then run the outer query on it, does it execute quickly? What does EXPLAIN look like?

The outer query

It takes ages to get the explain plan:

root@MISC m3[phabricator_search]> explain SELECT documentPHID, MAX(fieldScore) AS documentScore FROM (SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore FROM `search_document` document JOIN `search_documentfield` field ON field.phid = document.phid JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open' WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000) query JOIN `search_document` root ON query.documentPHID = root.phid GROUP BY documentPHID ORDER BY documentScore DESC LIMIT 0, 100;
+------+-------------+------------+----------+------------------+------------+---------+-------------------------------+------+------
| id   | select_type | table      | type     | possible_keys    | key        | key_len | ref                           | rows | Extra
+------+-------------+------------+----------+------------------+------------+---------+-------------------------------+------+------
|    1 | PRIMARY     | <derived2> | ALL      | NULL             | NULL       | NULL    | NULL                          |    2 | Using
|    1 | PRIMARY     | root       | eq_ref   | PRIMARY          | PRIMARY    | 66      | query.documentPHID            |    1 | Using
|    2 | DERIVED     | field      | fulltext | phid,key_corpus  | key_corpus | 0       |                               |    1 | Using
|    2 | DERIVED     | statuses   | ref      | phid,relation    | phid       | 66      | phabricator_search.field.phid |    1 | Using
|    2 | DERIVED     | document   | eq_ref   | PRIMARY,key_type | PRIMARY    | 66      | phabricator_search.field.phid |    1 | Using
+------+-------------+------------+----------+------------------+------------+---------+-------------------------------+------+------
5 rows in set (11 min 49.06 sec)

The query itself, I tried it again but killed it manually after 10 minutes as I didn't want to kill the server.
But I noticed this:

| 50776 | root            | localhost        | phabricator_search | Query   |   605 | **//FULLTEXT initialization//**                                                     | SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpu

• Is the combination of the two queries the problem?

More broadly: Assuming the inner query is the issue, why does the inner query take a long time to return? Why does it consume a large amount of memory given that it has LIMIT 1000 with no ORDER clause? (This query may be written in a bad way that I'm just out of my depth on, and I'm not sure what to do in order to try to answer these questions.)

In T156905#2989959, @Marostegui wrote:

| 50776 | root            | localhost        | phabricator_search | Query   |   605 | **//FULLTEXT initialization//**                                                     | SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpu

So could that FULLTEXT initialization be eating up all the memory?
it definitely put some load on the server: https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1048&var-network=eth0&from=now-6h&to=now

Hrrm. For comparison, a similar inner query on secure.phabricator.com (searching for "phabricator" instead of "affecting translatewiki.net"; and we're on MySQL, not MariaDB) executes in 1.3s. You have something like 10x more data than we do, but the query takes 1,300x longer to execute.

How long does this simpler query -- which only uses the FULLTEXT index -- take?

SELECT phid FROM `search_documentfield` field
  WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) LIMIT 1000;

What if we dropped the phabricator_search table then re created and then do the reindexing for mysql, would that work?

In T156905#2989991, @epriestley wrote:

Hrrm. For comparison, a similar inner query on secure.phabricator.com (searching for "phabricator" instead of "affecting translatewiki.net"; and we're on MySQL, not MariaDB) executes in 1.3s. You have something like 10x more data than we do, but the query takes 1,300x longer to execute.

How long does this simpler query -- which only uses the FULLTEXT index -- take?

SELECT phid FROM `search_documentfield` field
  WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) LIMIT 1000;

It took:

12 rows in set (11 min 6.48 sec)

And this ate most of the time:

575 | FULLTEXT initialization

Here's another possible formulation of the query based on Googling "FULLTEXT initialization", although I haven't yet found a real description of what's going on, just a lot of Stackoverflow posts about MySQL misbehaving. I'd expect this to do worse than the original query in a world where MySQL FULLTEXT indexes behave mostly like other indexes:

SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore,
  field.phidType,
  document.documentType
FROM `search_document` document
JOIN (
  SELECT * FROM search_documentfield
  WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE)
  AND phidType IN ('TASK')
) field ON field.phid = document.phid
JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
WHERE document.documentType = 'TASK'
LIMIT 1000;

Maybe tuning innodb_ft_cache_size and innodb_ft_total_cache_size is needed. Little to no tuning was done after converting the table from MyISAM to InnoDB.

Ah! That seems pretty broken -- the same simple query takes 0.03s on secure.phabricator.com, so yours is ~22,000x slower for ~10x more data.

There's one StackOverflow answer here which suggests this can happen if a lot of rows have been deleted (which realistically has happened during reindexing), and that a possible fix is just to OPTIMIZE the table:

http://dba.stackexchange.com/a/106628

That feels pretty flimsy to me, but if we can't get the simple case (just ...WHERE MATCH... with no fancy stuff) working quickly we don't have any easy solutions on the Phabricator side.

Is that something you're comfortable trying?

Is that something you're comfortable trying?

Yes, that makes lot of sense, too.

Tuning innodb_ft_* parameters may also be fruitful, but I don't have any direct experience with it to provide guidance.

In T156905#2990030, @epriestley wrote:

Ah! That seems pretty broken -- the same simple query takes 0.03s on secure.phabricator.com, so yours is ~22,000x slower for ~10x more data.

There's one StackOverflow answer here which suggests this can happen if a lot of rows have been deleted (which realistically has happened during reindexing), and that a possible fix is just to OPTIMIZE the table:

http://dba.stackexchange.com/a/106628

That feels pretty flimsy to me, but if we can't get the simple case (just ...WHERE MATCH... with no fancy stuff) working quickly we don't have any easy solutions on the Phabricator side.

Is that something you're comfortable trying?

Yes, we can try that on the slave and see what happens.

It is interesting that I was running your query above, and tried to kill it and it looks like killed but still there trying to initiate the Full Text index.

| 54541 | root            | localhost        | phabricator_search | Killed  |   387 | FULLTEXT initialization                                                     | SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpu

I will optimize the tables once the kill has happened.

In T156905#2990021, @jcrespo wrote:

Maybe tuning innodb_ft_cache_size and innodb_ft_total_cache_size is needed. Little to no tuning was done after converting the table from MyISAM to InnoDB.

Indeed - I had a chat with @Paladox earlier today and we were looking into that

Mentioned in SAL (#wikimedia-operations) [2017-02-01T16:18:45Z] <marostegui> Optimizing table search_documentfield on db1048 - T156905

If we can't get the trivial SELECT * WHERE MATCH(...) case performing quickly, I believe the engine isn't going to be usable no matter how clever we are with nesting queries and doing joins, and we have to move away from it.

I'd like to understand exactly why the FULLTEXT index is degrading to what looks like a table scan in the basic case, but that might be a long road to go down.

To move away from the engine, I think there are two major ways forward:

1. move to ElasticSearch (or some similar dedicated indexing server);
2. write a custom fulltext engine using normal MySQL tables and indexes instead of FULLTEXT, which we just write off as irreparably broken.

(2) isn't quite as insane as it sounds: we already implement an "ngram" engine for substring search (https://secure.phabricator.com/T9979). This would also give us control over all the weird edge cases where users expect duck.quack to tokenize in a particular way. It would give us a pathway toward Chinese/Japanese/Korean fulltext support, too.

In the near term, the advantage of implementing fulltext using normal MySQL primitives is that we could drive it entirely on our side and just have you run a couple scripts at the end, while ElasticSearch requires more setup and ongoing operational support on your side. However, I think a lot of that is already in production in some capacity (T155299?) so the barriers around ElasticSearch may be fairly low.

Of course, ideally the OPTIMIZE just works, solves the problem, and then we maybe look at having bin/storage upgrade periodically run it during adjustment so you can forget about it.

We have elastic search as an experimental option. You can enable it through the pref by going to Developer Settings and under the elastic search section.

Though elastic earch could still gain some improvements in it's searching in phablet. It find things that mysql couldn't.

@mmodell has been working hard on improving elastic search support :)

We could possibly forward the updates @mmodell did to support elasticsearch 2. He also further improved support for elasticsearch 5. But needs a fix to prevent the index warning about elasticsearch for elasticsearch 5.

Good news:

root@MISC m3[phabricator_search]> optimize table search_documentfield;
Stage: 1 of 2 'copy to tmp table'  0.023% of stage done
Stage: 1 of 2 'copy to tmp table'   40.9% of stage done
+-----------------------------------------+----------+----------+-------------------------------------------------------------------+
| Table                                   | Op       | Msg_type | Msg_text                                                          |
+-----------------------------------------+----------+----------+-------------------------------------------------------------------+
| phabricator_search.search_documentfield | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
| phabricator_search.search_documentfield | optimize | status   | OK                                                                |
+-----------------------------------------+----------+----------+-------------------------------------------------------------------+
2 rows in set (7 min 28.26 sec)

Now the query that @epriestley suggested and that previously took 11 minutes:

root@MISC m3[phabricator_search]> SELECT phid FROM `search_documentfield` field                                                          ->   WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) LIMIT 1000;
<snip>
18 rows in set (1 min 59.10 sec)

The inner query that took around 22 minutes before now takes:

root@MISC m3[phabricator_search]> SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore
    ->   FROM `search_document` document
    ->   JOIN `search_documentfield` field ON field.phid = document.phid
    ->   JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
    ->   WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000;
<snip>
13 rows in set (1 min 59.58 sec)

I am going to try the big query too.

And the big query finished in 5 rows in set (1 min 59.41 sec):

root@MISC m3[phabricator_search]> SELECT documentPHID, MAX(fieldScore) AS documentScore FROM (SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore FROM `search_document` document JOIN `search_documentfield` field ON field.phid = document.phid JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open' WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000) query JOIN `search_document` root ON query.documentPHID = root.phid GROUP BY documentPHID ORDER BY documentScore DESC LIMIT 0, 100;
<snip>
5 rows in set (1 min 59.41 sec)

I am going to go ahead and optimize this table on db2012 and on the master

but our only problem with elasticsearch is you can't reindex both indexes. So elasticsearch index is out of date.

we need someway to be able to index both at the same time and probly allow users to choose between elastic search and mysql either if one or the other is enabled :)

In T156905#2989343, @Volans wrote:

Looks like there was some heavy load on the server in the ~20 minutes before the OOM:

https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1043&var-network=eth0&from=1485940393438&to=1485942289902

Screenshot for reference:

Let's still try to tune the innodb parameters. 2 minutes is also too much for a simple search.

Run optimize after an upgrade is something we should keep in mind for the future.

In T156905#2990175, @Nemo_bis wrote:

In T156905#2989343, @Volans wrote:

Looks like there was some heavy load on the server in the ~20 minutes before the OOM:

https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1043&var-network=eth0&from=1485940393438&to=1485942289902

Screenshot for reference:

wow that's a lot of memory being used especially look at the cpu.

In T156905#2990176, @jcrespo wrote:

Let's still try to tune the innodb parameters. 2 minutes is also too much for a simple search.

yep, but that is done through puppet though. (I mean phabricator's my.conf file is done through puppet.)

Mentioned in SAL (#wikimedia-operations) [2017-02-01T16:54:22Z] <marostegui> Optimize table phabricator_search.search_documentfield on db2012 - T156905

In T156905#2990176, @jcrespo wrote:

Let's still try to tune the innodb parameters. 2 minutes is also too much for a simple search.

Agreed!
db2012 was optimized and will do the master tomorrow morning as we'll have less traffic.
This optimize WILL LOCK the table as it contains a full text index.

Normally optimize table can be done online, but it is not supported for full text indexes.

In T156905#2989959, @Marostegui wrote:

Hey @epriestley - thanks for the fast response!

In T156905#2989711, @epriestley wrote:

I'm not sure why the query is slow or requires a significant amount of memory. The structure of the query specifically tries to avoid this, by sacrificing result quality to limit the cost of the query, but perhaps the structure of the query can be improved.

Here's the overall problem I have tried to solve with this query:

• If a user queries for a very common term, they may match an extremely large number of results.
• Matching all those results and then ranking them could potentially require a large amount of memory.
• Avoid this by sacrificing result quality: initially match no more than 1,000 results, then rank just those results.

The intent is to give users results quickly when they execute an excessively broad search. The theory is: their search is probably too broad anyway, even if we rank the entire set of documents; and the cost of examining the entire set of documents is potentially very large.

The inner query is:

SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore
  FROM `search_document` document
  JOIN `search_documentfield` field ON field.phid = document.phid
  JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
  WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000

Note that this is a LIMIT 1000 with no ORDER clause. The intent is to let the database select the first 1,000 rows it can find (here: open tasks matching the search terms), without needing to build or sort a large result set. The intent is that if a user queries for search terms with a very large number of matches, we throw away 99% of them immediately in order to keep the working set small.

The outer query just groups and sorts the 1,000 results returned by the inner query.

It would be helpful to understand:

• Is the inner query the problem on its own? When run in isolation, does it execute quickly? What does EXPLAIN look like?

The inner query takes QUITEto execute:

root@MISC m3[phabricator_search]>   select @@hostname;
+------------+
| @@hostname |
+------------+
| db1048     |
+------------+
1 row in set (0.00 sec)

SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore
    ->   FROM `search_document` document
    ->   JOIN `search_documentfield` field ON field.phid = document.phid
    ->   JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'
    ->   WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000;
5 rows in set (22 min 32.80 sec)

This is the explain:

root@MISC m3[phabricator_search]> explain SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore   FROM `search_document` document   JOIN `search_documentfield` field ON field.phid = document.phid   JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open'   WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000;
+------+-------------+----------+----------+------------------+------------+---------+-------------------------------+------+-------------+
| id   | select_type | table    | type     | possible_keys    | key        | key_len | ref                           | rows | Extra       |
+------+-------------+----------+----------+------------------+------------+---------+-------------------------------+------+-------------+
|    1 | SIMPLE      | field    | fulltext | phid,key_corpus  | key_corpus | 0       |                               |    1 | Using where |
|    1 | SIMPLE      | statuses | ref      | phid,relation    | phid       | 66      | phabricator_search.field.phid |    1 | Using where |
|    1 | SIMPLE      | document | eq_ref   | PRIMARY,key_type | PRIMARY    | 66      | phabricator_search.field.phid |    1 | Using where |
+------+-------------+----------+----------+------------------+------------+---------+-------------------------------+------+-------------+
3 rows in set (0.00 sec)

• Is the outer query the problem on its own? If you SELECT the inner query into a temporary table, then run the outer query on it, does it execute quickly? What does EXPLAIN look like?

The outer query

It takes ages to get the explain plan:

root@MISC m3[phabricator_search]> explain SELECT documentPHID, MAX(fieldScore) AS documentScore FROM (SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AS fieldScore FROM `search_document` document JOIN `search_documentfield` field ON field.phid = document.phid JOIN `search_documentrelationship` AS `statuses` ON `statuses`.phid = document.phid AND `statuses`.relation = 'open' WHERE MATCH(corpus, stemmedCorpus) AGAINST ('+\"affecting\" +\"translatewiki.net\"' IN BOOLEAN MODE) AND field.phidType IN ('TASK') AND document.documentType IN ('TASK') LIMIT 1000) query JOIN `search_document` root ON query.documentPHID = root.phid GROUP BY documentPHID ORDER BY documentScore DESC LIMIT 0, 100;
+------+-------------+------------+----------+------------------+------------+---------+-------------------------------+------+------
| id   | select_type | table      | type     | possible_keys    | key        | key_len | ref                           | rows | Extra
+------+-------------+------------+----------+------------------+------------+---------+-------------------------------+------+------
|    1 | PRIMARY     | <derived2> | ALL      | NULL             | NULL       | NULL    | NULL                          |    2 | Using
|    1 | PRIMARY     | root       | eq_ref   | PRIMARY          | PRIMARY    | 66      | query.documentPHID            |    1 | Using
|    2 | DERIVED     | field      | fulltext | phid,key_corpus  | key_corpus | 0       |                               |    1 | Using
|    2 | DERIVED     | statuses   | ref      | phid,relation    | phid       | 66      | phabricator_search.field.phid |    1 | Using
|    2 | DERIVED     | document   | eq_ref   | PRIMARY,key_type | PRIMARY    | 66      | phabricator_search.field.phid |    1 | Using
+------+-------------+------------+----------+------------------+------------+---------+-------------------------------+------+------
5 rows in set (11 min 49.06 sec)

The query itself, I tried it again but killed it manually after 10 minutes as I didn't want to kill the server.
But I noticed this:

| 50776 | root            | localhost        | phabricator_search | Query   |   605 | **//FULLTEXT initialization//**                                                     | SELECT document.phid AS documentPHID, IF(field.field = 'titl', 1024, 0) + MATCH(corpus, stemmedCorpu

• Is the combination of the two queries the problem?

More broadly: Assuming the inner query is the issue, why does the inner query take a long time to return? Why does it consume a large amount of memory given that it has LIMIT 1000 with no ORDER clause? (This query may be written in a bad way that I'm just out of my depth on, and I'm not sure what to do in order to try to answer these questions.)

Looking at the order by, there is some performance improvements in mariadb 10.1. See https://mariadb.com/kb/en/mariadb/improvements-to-order-by/ please.

Also see http://s.petrunia.net/blog/?p=103

This has happened again and crashed the master and the slave.
I have run the ALTER table to optimize the table on the master while we were on read only.

I wonder why the slave crashed if the query, when I tried it, took 2 minutes....(reminder: this server had the table optimized).
So looks like we haven't solved the issue...

removing m3 from dbstore2001: db1043-bin.001457:753455796

incident report: https://wikitech.wikimedia.org/wiki/Incident_documentation/20170201-Phabricator

Mentioned in SAL (#wikimedia-operations) [2017-02-02T07:41:54Z] <marostegui> Restart MySQL on db2012 to tune some innodb_ft flags - T156905

Hi,

Some tests I have been doing:

• Executed the same query on db1048 (slave that crashed - OOM). Query took 2 minutes (as it did yesterday) but the server didn't crash.

Checked the last insert on that host before the crash just in case, but it is not even related to the problematic table

INSERT INTO `search_indexversion` (objectPHID, extensionKey, version)
        VALUES ('PHID-TASK-sobshatb24lkqo26e54u', 'fulltext', '2679053:none')
        ON DUPLICATE KEY UPDATE version = VALUES(version)

• Tunning innodb_ft_cache_size and innodb_ft_total_cache_size on db2012:

I have been changing their values (and rebuilding the index, and trying to get the table in memory) and there has not been any significant change in performance.
The last test I did was setting innodb_ft_total_cache_size to its max allowed value (1.6G) and innodb_ft_cache_size to the max value too (80MB). There has been no significant changes to the query speed.

• I have run 10 parallel threads on db2012 (several times) with the big query and I have not brought down db2012 even though I have generated more load than the one db1048 had when it crashed yesterday. I have run those 10 threads with and without the defaults values for innodb_ft_cache_size and innodb_ft_total_cache_size :

db2012: https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db2012&var-network=eth0&from=now-24h&to=now
db1048: https://grafana.wikimedia.org/dashboard/file/server-board.json?var-server=db1048&var-network=eth0&from=now-24h&to=now

Note that db2012 wasn't using as much memory as db1048 when it crashed.

Also running two threads with the big query on db1048 didn't make it crash. There was just a small increase on memory (expected), but that is it. Not like yesterday where before the crash it go a 10GB of used RAM increase (and swapped)

I think the problem was compounded by search-as-you-type which fires off a bunch of queries in rapid succession as you type a search term in the 'edit related tasks' dialog box.

Elasticsearch is actually a long term fix. I think we have permanently moved to it. We were preparing to move to it before. :)

In T156905#3024783, @Paladox wrote:

Elasticsearch is actually a long term fix. I think we have permanently moved to it. We were preparing to move to it before. :)

Thanks - I meant the initial way to triage it :-)
But I agree, ES is probably a better way to handle the search than MySQL for this particular case. I guess you guys were planning to move to ES eventually but maybe this rushed it a tiny bit ;-)
Thanks!!

Yep, @mmodell has improved searching by a lot :)