Optimize of pc1009 (and replica) finished.

Disk space usage went from 3.9TB to 2TB.

It ran from 2021-06-10T10:28:26+00:00 to 2021-06-10T18:39:59+00:00 (~8.2h)

TODO:

• Make pc1009 the pc3 primary again: https://gerrit.wikimedia.org/r/c/operations/mediawiki-config/+/700026
• Run stop slave; reset slave all on pc1009, so it stops replicating from pc1010
• Move pc1010 back to pc1: https://gerrit.wikimedia.org/r/c/operations/puppet/+/700047
• Truncate pc1010
• Set pc1010 replicating from pc1007

Change 700047 had a related patch set uploaded (by Kormat; author: Kormat):

[operations/puppet@production] pc1010: Move back to pc1, now that the maintenance is done.

https://gerrit.wikimedia.org/r/700047

Mentioned in SAL (#wikimedia-operations) [2021-06-16T09:40:37Z] <kormat@deploy1002> Synchronized wmf-config/db-eqiad.php: Repool pc1009 as pc3 primary T282761 (duration: 00m 59s)

Change 700047 merged by Kormat:

[operations/puppet@production] pc1010: Move back to pc1, now that the maintenance is done.

https://gerrit.wikimedia.org/r/700047

Mentioned in SAL (#wikimedia-operations) [2021-06-16T09:47:19Z] <kormat> truncating all pc* tables on pc1010 T282761

We're back to 67 hours today.

The queries that purgeParserCache sends are... weird, and more expensive than necessary.

E.g.:

DELETE /* SqlBagOStuff::deleteServerObjectsExpiringBefore */ FROM `pc134` WHERE (exptime < '20210621085036') AND keyname IN ('commonswiki:pcache:idoptions:71610166', 'skwiki:pcache:idhash:24341-0!canonical!responsiveimages=0', 'enwiki:pcache:idhash:36722755-0!canonical', 'commonswiki:pcache:idoptions:99175521', 'wikidatawiki:pcache:idhash:4725620-0!termboxVersion=22!userlang=de!wb=3!responsiveimages=0', 'commonswiki:pcache:idhash:90369939-0!canonical', 'itwiki:pcache:idoptions:4202454', 'enwiki:pcache:idhash:24256794-0!canonical', 'commonswiki:pcache:idoptions:86194370', 'ruwiki:pcache:idhash:2589508-0!canonical!responsiveimages=0', 'enwiki:pcache:idhash:24062326-0!canonical', 'commonswiki:pcache:idhash:4880597-0!canonical', 'commonswiki:pcache:idoptions:93201262', 'ruwiki:pcache:idhash:4136023-0!canonical!tmh-videojs', 'enwiki:pcache:idoptions:24251270', 'cebwiki:pcache:idhash:1691532-0!canonical!responsiveimages=0', 'commonswiki:pcache:idhash:35750027-1!userlang=ms!wb=3', 'wikidatawiki:pcache:idoptions:94489761', 'enwiki:pcache:idoptions:24046838', 'enwiki:pcache:idhash:30211084-0!numberheadings=1!thumbsize=3!userlang=de', 'enwiki:pcache:idoptions:58959373', 'enwiki:pcache:idoptions:24226310', 'enwiki:pcache:idhash:58893293-0!canonical', 'arzwiki:pcache:idhash:1124829-0!canonical!responsiveimages=0', 'enwiki:pcache:idhash:24249770-0!canonical', 'commonswiki:pcache:idhash:94786177-1!userlang=fr!wb=3', 'shwiki:pcache:idhash:3802096-0!canonical', 'wikidatawiki:pcache:idoptions:78749276', 'enwiki:pcache:idhash:58921469-0!canonical', 'enwiki:pcache:idhash:58947293-0!canonical', 'enwiki:pcache:idhash:58934889-0!canonical', 'enwiki:pcache:idhash:24213614-0!canonical', 'commonswiki:pcache:idhash:19004326-0!canonical', 'enwiki:pcache:idoptions:24058866', 'wikidatawiki:pcache:idhash:99437196-0!termboxVersion=22!wb=3!responsiveimages=0', 'ruwiktionary:pcache:idhash:786222-0!canonical!responsiveimages=0', 'zhwiki:pcache:idhash:2378231-0!canonical!zh-hant', 'zhwikisource:pcache:idhash:294844-0!canonical!zh-hans', 'commonswiki:pcache:idhash:71700898-0!wb=3', 'enwiki:pcache:idhash:58976469-0!canonical', 'frwiktionary:pcache:idoptions:2439030', 'wikidatawiki:pcache:idhash:872666-0!termboxVersion=1!wb=3', 'enwiki:pcache:idoptions:58903361', 'specieswiki:pcache:idhash:1409592-0!canonical!responsiveimages=0', 'srwiki:pcache:idhash:865929-0!userlang=sr-ec!sr-ec!responsiveimages=0', 'enwiki:pcache:idhash:24182714-0!canonical', 'itwiki:pcache:idoptions:6381937', 'zh_yuewiki:pcache:idhash:11417-0!canonical', 'wikidatawiki:pcache:idoptions:43834192', 'zhwiktionary:pcache:idhash:295216-0!userlang=zh-hans!zh-hans', 'commonswiki:pcache:idoptions:101845492', 'wikidatawiki:pcache:idoptions:93935984', 'commonswiki:pcache:idhash:101916466-0!thumbsize=7!wb=3', 'elwiktionary:pcache:idhash:100726-0!canonical', 'commonswiki:pcache:idoptions:41926142', 'commonswiki:pcache:idhash:7372137-1!wb=3', 'enwiki:pcache:idoptions:24050602', 'enwiki:pcache:idhash:58921933-0!canonical', 'enwiki:pcache:idoptions:24065738', 'tawiki:pcache:idoptions:11149', 'elwiki:pcache:idoptions:149075', 'commonswiki:pcache:idhash:71508282-0!wb=3', 'enwiki:pcache:idoptions:24243434', 'enwiki:pcache:idoptions:58887593', 'trwiki:pcache:idhash:2760344-0!canonical', 'commonswiki:pcache:idhash:52816220-1!userlang=nl!wb=3', 'wikidatawiki:pcache:idoptions:27666338', 'wikidatawiki:pcache:idoptions:41567642', 'wikidatawiki:pcache:idhash:6884476-0!termboxVersion=22!wb=3!responsiveimages=0', 'wikidatawiki:pcache:idhash:74232927-0!termboxVersion=22!wb=3!responsiveimages=0', 'commonswiki:pcache:idhash:71702234-0!wb=3', 'commonswiki:pcache:idhash:30485637-1!wb=3', 'enwiki:pcache:idhash:24128150-0!canonical', 'enwiki:pcache:idhash:24159162-0!canonical', 'commonswiki:pcache:idhash:17722176-1!userlang=vi!wb=3', 'enwiki:pcache:idhash:24147430-0!canonical', 'commonswiki:pcache:idhash:4825927-0!wb=3', 'urwiki:pcache:idhash:121007-1!canonical', 'dawiktionary:pcache:idhash:14302-0!canonical!responsiveimages=0', 'enwiki:pcache:idhash:58943453-0!canonical', 'commonswiki:pcache:idhash:75308860-0!wb=3', 'commonswiki:pcache:idhash:19827132-0!userlang=de!responsiveimages=0', 'trwiki:pcache:idoptions:1430198', 'enwiki:pcache:idoptions:24127406', 'zhwiki:pcache:idhash:4885077-0!canonical!zh-tw', 'enwikisource:pcache:idoptions:3339960', 'commonswiki:pcache:idhash:71563990-0!wb=3', 'enwiki:pcache:idhash:24292610-0!canonical', 'frwiki:pcache:idoptions:12645537', 'commonswiki:pcache:idhash:71612598-0!canonical', 'ruwikinews:stable-pcache:idoptions:466463', 'zhwiki:pcache:idhash:6024646-0!canonical!zh-hk', 'enwikinews:pcache:idoptions:2331881', 'hywiki:pcache:idhash:801694-0!canonical', 'enwikinews:pcache:idhash:2331437-0!canonical', 'commonswiki:pcache:idhash:29136537-0!wb=3!responsiveimages=0', 'commonswiki:pcache:idhash:71483186-0!canonical', 'enwikisource:pcache:idoptions:3323604', 'commonswiki:pcache:idhash:85429047-0!wb=3!responsiveimages=0', 'commonswiki:pcache:idhash:98070845-0!wb=3') /* 39c789a879b3532550b5cacffd54efa6 pc1007 parsercache 2s */

What i was expecting is:

DELETE FROM `pc134` WHERE (exptime < '20210621085036') limit 1000;

I did some digging into the codebase and (assuming my lack of php knowledge didn't lead me astray ;) it looks like the function that does the actual work is here:

https://doc.wikimedia.org/mediawiki-core/master/php/SqlBagOStuff_8php_source.html#l00737

On each pc* table it runs a select to find rows that should be expired, and then deletes them, instead of just getting the db to do it in one go.

In terms of expensiveness, looking at the table schema, it is going to be down to the amount of rows each transaction will be deleting. From what I can see with some similar queries, looks like the current delete is cheaper (it scans less rows), but it is only selecting 81 rows, so we'd need to check with a table that would be deleting more.

What I am really surprise is to see we actually run a SELECT + ORDER BY before each delete, I guess that's needed to narrow the delete itself?
The SELECT isn't super expensive, but it is definitely some overhead:

 root@pc2010.codfw.wmnet[parsercache]> explain  select keyname,exptime  from `pc069` WHERE (exptime < '20210621085036') order by exptime asc;
+------+-------------+-------+-------+---------------+---------+---------+------+--------+--------------------------+
| id   | select_type | table | type  | possible_keys | key     | key_len | ref  | rows   | Extra                    |
+------+-------------+-------+-------+---------------+---------+---------+------+--------+--------------------------+
|    1 | SIMPLE      | pc069 | range | exptime       | exptime | 6       | NULL | 322778 | Using where; Using index |
+------+-------------+-------+-------+---------------+---------+---------+------+--------+--------------------------+
1 row in set (0.034 sec)

root@pc2010.codfw.wmnet[parsercache]>select keyname,exptime  from `pc100` WHERE (exptime < '20210621085036') order by exptime asc;

139901 rows in set (0.358 sec)

If we are doing the SELECT to build the DELETE from above, we should probably look into the amount of time the SELECT+DELETE takes in comparison with just a DELETE FROM XXX WHERE (exptime < 'XXX') limit XXX;

The above tests were done in a 100% idle host by the way.

Current status: the purge has been running for ~28h, and is at 15% progress. That extrapolates to ~8 days total for this run.

@Krinkle @aaron do you happen to know if there is a specific reason to do the deletes in the above way?

FWIW, looking at the code above I am under the impression that the SELECT+DELETE is only needed to gather some stats for progress estimate: the SELECTed rows are read to find out the minimum and maximum expiry being deleted. Perhaps, if the SELECT has a noticeable overhead, it would be acceptable to have less accurate statistics?

Also, I believe that the exptime < 'xxx' condition in the DELETE is unnecessary. The keynames come from the SELECT query above, which uses the same comparison. Is it there to ensure atomicity? Or can it be removed?

In T282761#7169015, @Kormat wrote:

What I was expecting is:

DELETE FROM `pc134` WHERE (exptime < '20210621085036') limit 1000;

In T282761#7169546, @LSobanski wrote:

Do you happen to know if there is a specific reason to do the deletes in the above way?

It's hard to be sure since the code is so old, but based on today's best practices I would retroactively say that for production code our policy is generally to only perform writes or deletes by primary key. This is for performance, but also to be determistic and safe under various other conditions. I suppose it also helps with row-based replication. I understand parser caches could be exempt from this, as they are special in various ways, but from a code perspective we currently treat it like we treat anything else in production.

In T282761#7169569, @Daimona wrote:

The exptime < 'xxx' condition in the DELETE is unnecessary. […] Or can it be removed?

No. The keys are canonical/determinitic, based on page IDs. And at any moment, when a wiki page is accessed relating to the expired row, MediaWiki may regenerate the value and replace the row in question, with a new value and new expiry. Thus the exptime condition needs to be there, I think.

Summary of meeting between @aaron, @LSobanski and myself yesterday:

In the last two months, we did forced purges in this task over each of the servers while they were in a depooled state. There we found that it consistently took about 1.8 minutes for a single unlimited DELETE statement to return, where each DELETE was removing about 400k rows. These were DELETE statements for a single table, with only a WHERE clause for the exptime and nothing else. In total, it consistently took about 8 hours to purge a single server, where each of the 255 tables were purged back-to-back with no batching, no limit, no sleeps. Script at P16060.

It seems from the various samples we took, that there are typically around 200k rows that expiry on any given day in any given table (255 tables, 3 servers). In practice currently we typically are having to remove 400k rows or more per table, because we're several days behind thus more expired data has to be removed at once. This is plausibly confirmed by emperical data from MySQL stats, where we see 500 write queries per second, which amounts to (500*3600*24)/255, or 170k new rows per-day per-table.

Aaron helped us analyse MySQL stats and EXPLAIN operations during the select and delete operations and we did not find anything concerning there. The handler stats show read_next and delete both counting about 150 per second. Specifically, there were not additional reads directly or indirectly happening during the delete operation, which could perhaps have suggested improper index use etc. Handler stats for the SELECT queries such as SELECT keyname,exptime FROM pc130 WHERE exptime < '20210622000000' AND exptime >= '20210618134451' ORDER BY exptime ASC LIMIT 100;:

wikiadmin@10.64.16.20(parsercache)> show session status LIKE 'handler_read%';
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| Handler_read_first       | 0     |
| Handler_read_key         | 1     |
| Handler_read_last        | 0     |
| Handler_read_next        | 99    |
| Handler_read_prev        | 0     |

The explain for the delete looked at follows:

| hiwiki:pcache:idhash:1082758-0!canonical                          | 2021-06-18 13:45:26 |          9126 |
+-------------------------------------------------------------------+---------------------+---------------+
30 rows in set (0.00 sec)

wikiadmin@10.64.16.20(parsercache)> EXPLAIN EXTENDED DELETE FROM pc130 WHERE exptime < '20210622000000' AND keyname IN ('hiwiki:pcache:idhash:1082758-0!canonical', 'zhwiki:pcache:idhash:1204182-0!canonical!zh-tw', 'commonswiki:pcache:idhash:79476467-1!userlang=zh!wb=3', 'hiwiki:pcache:idoptions:1057118');
+------+-------------+-------+-------+-----------------+---------+---------+------+------+----------+-------------+
| id   | select_type | table | type  | possible_keys   | key     | key_len | ref  | rows | filtered | Extra       |
+------+-------------+-------+-------+-----------------+---------+---------+------+------+----------+-------------+
|    1 | SIMPLE      | pc130 | range | keyname,exptime | keyname | 257     | NULL | 4    |   100.00 | Using where |
+------+-------------+-------+-------+-----------------+---------+---------+------+------+----------+-------------+
1 row in set (0.00 sec)

We did a basic calculation on how much time might be wasted in sleeps. Given 3 servers, 255 tables, 170k-400k rows to delete in each, batch size of 100, and a sleep of 0.5s, that amounts to (((3*255*170000)/100)*0.5)/3600/24 or... 7 days just for the sleeps? I don't think that can be right since I've used the lower end of the range of rows to expect, and afaik over the past 12 months there were plenty of weeks during which we also had the same insert/expire rate of 500 replace queries per second, and yet had purge runs complete in under 24 hours (for example MySQL stats shows in June 2020 we had more or less the same insert rate as today, but the task description shows purge runs of 3-4 days for that same time).. So... I'm probably doing something wrong here.

I laid out three broad ideas for how to move forward:

1. Reduce sleep duration (or increase batch size, effectively the same, sleep probably preferred). Also, we can improve it such that the sleep is an interval that includes the time for the delete query, thus representing more accurately the underlying use case, and naturally reducing idle time when queries take longer, and increasing it when they are faster.
2. Remove sleep entirely. This is something we probably don't want to do right since we still replicate to Codfw. But, as part of T277831, it semes like we're likely to stop doing replication once we're active-active, with the only remaining use until then being to have a warm standby for unplanned switchovers. Perhaps it's worth the operational benefit to stop replication and purge-sleeps now, and then try to keep them warm by other means (or to go without it until we're active-active).
3. Purge servers concurrently instead of one at a time (e.g. extra parameter for db server name, or spawn sub processes; non-trivial).

Also, to recap the reason for the sleeps. This was added in 2016 per T150124 to mitigate replication lag in the secondary datacentre. As I understand it, it's not that we think the delete statements themselves are lag-prone. These are only use primary keys, and are naturally spaced out by the time it takes for the primary DB to process the delete. The queries are all issues by a single process in a single thread, no concurrenty or other gracefulness to worry about. However, while the delete statements themselves might not cause lag, we do have to consider the regular production traffic which involves lots of inserts (500 per second), and those are more-or-less unthrottled based on user demand. So the sleeps are a way to avoid congesting this more important events in the replication stream with deletes.

Now, having said that, it seems that at least today, the delete operations themselves are fairly time-consuming already, so perhaps the sleeps no longer are as needed as they used to be. Although it's worth trying to figure out why they take as long as they do. The above didn't give us anything concerning about the queries, the indexes etc., but the reality is that it still took 8 hours unthrottled on a depooled server to delete the data in question. If the problem isn't in the index, the schema, or the queries, then perhaps there's something at the hardware or mysql tuning side that perhaps offers a clue for making these operations faster. Aaron mentioned two thing that may be worth looking into:

1. Threshold for page splitting/merging.
2. Threshold for inlining blobs.

I don't know anything about these though, beyond what the mysql manual says about them, but I'll document it here for posterity.

The plan for today was to start by reducing the sleep and then run it again to see how much it helps.

I was looking at some of the host stats with @Gilles earlier today, and he asked what the main bottleneck is on the MySQL side. E.g. is it maxing out CPU, or maxing out disk. If neither, then what is holding it up? We looked at the MySQL stats during the manual purge on 25 May and correlated them with the Host overview: pc1007 and it seemed that the bottleneck is disk I/O. During this unthrottled purge, disk utilization was around 90%. Perhaps this is obvious, but I thought it was interesting nonetheless.

Change 700957 had a related patch set uploaded (by Krinkle; author: Krinkle):

[operations/puppet@production] mediawiki: Reduce purgeParserCache.php sleep from 500ms to 200

https://gerrit.wikimedia.org/r/700957

>>>! In T282761#7169546, @LSobanski wrote:

Do you happen to know if there is a specific reason to do the deletes in the above way?

It's hard to be sure since the code is so old, but based on today's best practices I would retroactively say that for production code our policy is generally to only perform writes or deletes by primary key. This is for performance, but also to be determistic and safe under various other conditions. I suppose it also helps with row-based replication. I understand parser caches could be exempt from this, as they are special in various ways, but from a code perspective we currently treat it like we treat anything else in production.

Does this mean it's not an option or can we consider an exception for parser cache? It looks like a promising way forward.

Is the hypothesis that using by-exptime instead of by-primarykey queries for deletion would be notably faster and/or that the select queries are our bottleneck? I did not get that impression. It seemed like the deletes would be equally fast, or faster using the current primary key method, with the main time being spent on disk I/O to delete the data itself. Also taking into account that our manual purge run last month did already use this proposed by-exptime method, and that also took 8 hours per server.

But yes, we could rewrite the code to no longer batch by a limited number of rows, but instead batch by e.g. 10 min timestamp chunks (without row count limit?), or batch just blindly with LIMIT 100 applied to an otherwise complete DELETE for all expired rows. If your team suspect that the difference in row selection coudl be a primary contributor to it taking longer to purge and that changing it might bring us under 24h, we could prioritise that refactor. Do you think that?

I'm not sure of my exact motivation for using the primary key in 53d267b3dce25f7b9c7b4216456ad3850ea5035e instead of DELETE with LIMIT, but most likely it was done on the theory that it would reduce replication lag. The exptime index is not used for anything else, so it might not be in memory when the script runs. Loading primary keys with SELECT avoids replicating a hit on a cold index.

Also, according to the MySQL manual, DELETE with LIMIT generates a warning when used with statement-based replication, even if ORDER BY is used.

Also, DELETE with LIMIT is not standard SQL and IDatabase::delete() does not support it.

In T282761#7170212, @Krinkle wrote:

I laid out three broad ideas for how to move forward:

1. Reduce sleep duration (or increase batch size, effectively the same, sleep probably preferred). Also, we can improve it such that the sleep is an interval that includes the time for the delete query, thus representing more accurately the underlying use case, and naturally reducing idle time when queries take longer, and increasing it when they are faster.

+1 to reduce sleep time and/or batch size. Especially with the new hardware, I am pretty sure we can handle more load.

2. Remove sleep entirely. This is something we probably don't want to do right since we still replicate to Codfw. But, as part of T277831, it semes like we're likely to stop doing replication once we're active-active, with the only remaining use until then being to have a warm standby for unplanned switchovers. Perhaps it's worth the operational benefit to stop replication and purge-sleeps now, and then try to keep them warm by other means (or to go without it until we're active-active).

If we don't replicate to codfw, I am fine with that, but as you mention we still do. And further, we'll be doing the DC switchover next week, so I do not want to start with codfw delayed, not because it is a bad thing, but because I don't know how MW will handle reading from parsercache hosts with lag, but I supposed it will complain hardly :)

3. Purge servers concurrently instead of one at a time (e.g. extra parameter for db server name, or spawn sub processes; non-trivial).

Also, to recap the reason for the sleeps. This was added in 2016 per T150124 to mitigate replication lag in the secondary datacentre. As I understand it, it's not that we think the delete statements themselves are lag-prone. These are only use primary keys, and are naturally spaced out by the time it takes for the primary DB to process the delete. The queries are all issues by a single process in a single thread, no concurrenty or other gracefulness to worry about. However, while the delete statements themselves might not cause lag, we do have to consider the regular production traffic which involves lots of inserts (500 per second), and those are more-or-less unthrottled based on user demand. So the sleeps are a way to avoid congesting this more important events in the replication stream with deletes.

DELETES are very expensive on mysql indeed, but as you mention, these hosts have an additional load of writes and selects. Again, new hardware might help here, but yet to be tested.

1. Threshold for page splitting/merging.
2. Threshold for inlining blobs.

I don't know anything about these though, beyond what the mysql manual says about them, but I'll document it here for posterity.

The plan for today was to start by reducing the sleep and then run it again to see how much it helps.

This sounds good to me but keep in mind we are switching to codfw on Tuesday and we should not start with codfw lagged, unless you tell me MW will handle that without errors/warnings.

---

I was looking at some of the host stats with @Gilles earlier today, and he asked what the main bottleneck is on the MySQL side. E.g. is it maxing out CPU, or maxing out disk. If neither, then what is holding it up? We looked at the MySQL stats during the manual purge on 25 May and correlated them with the Host overview: pc1007 and it seemed that the bottleneck is disk I/O. During this unthrottled purge, disk utilization was around 90%. Perhaps this is obvious, but I thought it was interesting nonetheless.

I think there's not a single bottleneck here, it is probably a combination of many things.
We are generating lots of writes, as you mentioned, around 500 writes per second steadily, which is probably leading to contention too (which can be seeing here: https://grafana.wikimedia.org/d/000000273/mysql?viewPanel=19&orgId=1&from=now-24h&to=now&var-server=pc1007&var-port=9104).

There's also the fact that the current hardware is way different from what we are used to in production. This hardware has half the ram (256GB) and only 4 SSDs disks (in production we have 10), which means less speed as well. On top of this, we use RAID 5, here and not 10, which also means we have less performance on each write, and having this huge amount of writes can make lots of difference.
We have purchased new hardware (T284825) which is the same one we have in production (512GB RAM, 10 disks and RAID10), so this for sure will speed up things. So far only codfw hosts have arrived, but I think we should start doing tests there as soon as we can.
We can copy pc2010 (spare) data to the host that will be in pc1 codfw, and we can do testing with production data on at least one host.

In T282761#7171509, @tstarling wrote:

The exptime index is not used for anything else, so it might not be in memory when the script runs. Loading primary keys with SELECT avoids replicating a hit on a cold index.

That's actually a good approach indeed, but given how crazy parsercache has grown...it might be causing extra overload.

Also, according to the MySQL manual, DELETE with LIMIT generates a warning when used with statement-based replication, even if ORDER BY is used.

Yeah, mysql issues that warning as it is an unsafe statement, but given the nature of the parsercache data, maybe it would be ok to ignore it.

Change 700957 merged by Kormat:

[operations/puppet@production] mediawiki: Reduce purgeParserCache.php sleep from 500ms to 200

https://gerrit.wikimedia.org/r/700957

Notes from the meeting today with @Kormat and @Krinkle

• Code changes to be made:
  • Recording number of iterations since the last percentage print (purge script feature to be added).
  • Running on multiple servers (adding a --server parameter) requires changes to both the maintenance function in SqlBagOStuff and the script.
• Sleep interval deduction (making sleep variable instead of static) requires further data gathering.
• Filtering deletes from replication and running on both DCs would result in spare PC not getting purged but this won't be a problem once the script is host-aware.
• We can test the new hosts, they would have to be introduced as replicas first.

Change 701132 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] purgeParserCache.php: Print stats for time and iterations

https://gerrit.wikimedia.org/r/701132

For what is worth, I have tested the following changes on all eqiad pc hosts for a few hours each:
innodb_change_buffering to: deletes, purges, all.

They made no difference on the script speed, which remained around 10-11 minutes per 0.1% step.

I have set it back to none.

In T282761#7172556, @LSobanski wrote:

• Running on multiple servers (adding a --server parameter) requires changes to both the maintenance function in SqlBagOStuff and the script.

My idea was to reorder the deletes so that the inner loop is by server, rather than the outer loop. This would allow the delay to be tuned downwards (perhaps to zero) since while replication is catching up, the script will be busy with other servers. But --server would also work.

In T282761#7173997, @tstarling wrote:

In T282761#7172556, @LSobanski wrote:

• Running on multiple servers (adding a --server parameter) requires changes to both the maintenance function in SqlBagOStuff and the script.

My idea was to reorder the deletes so that the inner loop is by server, rather than the outer loop. This would allow the delay to be tuned downwards (perhaps to zero) since while replication is catching up, the script will be busy with other servers. But --server would also work.

Ack. I mentioned this in the meeting and was meant to be captured as part of the point "Sleep interval deduction (making sleep variable instead of static)" which would involve deducting time spent from the interval, as well as to further make use of that time by handling other servers at the same time – effectively inverting the loop as you say.

We discussed that how much this gains us depends on how much of the time is actually spent in the deletes vs in the sleep right now. Our napkin calculations suggested that even with near-zero sleep we may still be close to or over the 24h mark, so actually running them concurrently seemed to be simpler in terms of code refactoring and a bigger more certain step to getting under 24h. Although in the time since that meeting, I've come to believe we'll need multiple mitigations since 8 days divided 3 is still more than 1. Perhaps the reduced sleep will get us there, but if not we can still do the dynamic interval on top, it would only deduct the single write time from each iteration's sleep.

I did raise the concern that doing this concurrently would mean either hardcoding a new shard parameter in the cron config (and thus an awkward separation of concerns between MW and Puppet), or complexity in the shape of subprocesses/forks (not our favourite thing to do in PHP, but might be managable if we add the shard parameter anyway, and then spawn sub procs that set that parameter). I haven't yet decided which of the two is best, but I figured either way would involve a shard parameter, and that parameter seems relatively easy to implement. We could hardcode it at least to get started initially if we're not sure about sub procs yet.

@dpifke mentioned table partitioning. If we wanted to rearchitect it more aggressively, there are some ways we could avoid deletes altogether. For example, we could use a MultiWriteBagOStuff to write to two tiers of SQL cache. Then periodically wipe one tier and rotate the configured order of the tiers. When you introduce a new tier, a cache miss on the new tier causes the data to be copied from the old tier. It would be a LRU eviction scheme.

If DROP TABLE can be done without stalling the whole server, we could just use table prefixes for the tiers, and the whole thing could be automated in MediaWiki. We could have a new BagOStuff subclass that implements rotation automatically, instead of requiring a change to the config.

Change 701132 merged by jenkins-bot:

[mediawiki/core@master] purgeParserCache.php: Print stats for time and iterations

https://gerrit.wikimedia.org/r/701132

@Marostegui I was curious if adjusting MERGE_THRESHOLD would help (e.g https://dev.mysql.com/doc/refman/5.6/en/index-page-merge-threshold.html ) though INFORMATION_SCHEMA.INNODB_METRICS seems to not be enabled? Are those stats really expensive?

The current run has progressed to 10.4% over the course of 19h. That works out to ~7.6 days for a full run.

On the plus side, reducing the sleep duration doesn't appear to have had an impact on replication lag:

https://grafana-rw.wikimedia.org/d/000000273/mysql?orgId=1&from=1624352800983&to=1624525600983&var-server=pc2008&forceLogin=true&viewPanel=6

(purgeParserCache.php is currently running against pc1008; this is the codfw replica in the same section)

@Krinkle : another feature request for purgeParserCache.php would be to print the current section/host. I realise that that's not doable right now with the current code structure, but it would help quite a bit with correlating things.

Change 701285 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@wmf/1.37.0-wmf.11] purgeParserCache.php: Print stats for time and iterations

https://gerrit.wikimedia.org/r/701285

Change 701433 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] purgeParserCache.php: Implement --tag for purging one server only

https://gerrit.wikimedia.org/r/701433

Change 701433 merged by jenkins-bot:

[mediawiki/core@master] purgeParserCache.php: Implement --tag for purging one server only

https://gerrit.wikimedia.org/r/701433

Change 701408 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@wmf/1.37.0-wmf.11] purgeParserCache.php: Implement --tag for purging one server only

https://gerrit.wikimedia.org/r/701408

Change 701602 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] obectcache: made SqlBagOStuff::deleteObjectsExpiringBefore alternate over shards

https://gerrit.wikimedia.org/r/701602

The last purge run took 113h (4d 17h).
The current purge is currently at 2.3%, and at the current pace will take a total of 117h, so pretty comparable.

Change 701408 merged by jenkins-bot:

[mediawiki/core@wmf/1.37.0-wmf.11] purgeParserCache.php: Implement --tag for purging one server only

https://gerrit.wikimedia.org/r/701408

Mentioned in SAL (#wikimedia-operations) [2021-06-28T19:45:05Z] <krinkle@deploy1002> Synchronized php-1.37.0-wmf.11/includes/objectcache/SqlBagOStuff.php: T282761 - I618bc1e8ca3008 (duration: 00m 59s)

Mentioned in SAL (#wikimedia-operations) [2021-06-28T19:46:30Z] <krinkle@deploy1002> Synchronized php-1.37.0-wmf.11/includes/libs/objectcache/: T282761 - I618bc1e8ca3008 (duration: 00m 56s)

In T282761#7180211, @Kormat wrote:

The last purge run took 113h (4d 17h).
The current purge is currently at 2.3%, and at the current pace will take a total of 117h, so pretty comparable.

The scheduled script is currently doing pc3 (pc1009). I briefly ran a separate process with --tag pc2 (pc1008) to confirm that this works as expected in production. That is, the extra process is making progress (stdout below), and Grafana: mysql pc1008 shows delete queries kicking in, and the scheduled script continues unaffected at the same time at Grafana: mysql pc1009.

[21:41 UTC] krinkle at mwmaint1002.eqiad.wmnet in ~
$ mwscript purgeParserCache.php --wiki=aawiki --age=1814400 --msleep 200 --tag pc2
Deleting objects expiring before Mon, 28 Jun 2021 21:41:48 GMT
... 0.0% done
... 0.1% done

I'll leave it running from my gnu-screen as it seems very low risk at this point. Feel free to kill the proc if there is any amount of uncertainty, discomfort, or trouble.

Mentioned in SAL (#wikimedia-operations) [2021-06-28T21:55:01Z] <Krinkle> krinkle@mwmaint1002: purgeParserCache.php --tag pc2, ref T282761

Mentioned in SAL (#wikimedia-operations) [2021-06-29T00:25:56Z] <Krinkle> krinkle@mwmaint1002: purgeParserCache.php --tag pc1, ref T282761

The manual run for pc1 and pc2, as well as the scheduled run that was at pc3, as running on mwmaint1002.eqiad, were all cut-off by the switchover procedure. This was anticipated and we decided together with the DBAs to let this happen and restart manually on the other side (prioritising an uncomplicated/uneventful switchover, over the pressure on parsercaches which we think we can eat another 1-2 days into our margins for).

After the switchover was completed, I started three manual "tagged" runs around Tue 29 June, 18:00 UTC, on mwmaint2002.codfw.

• pc1 (pc2007/pc1007): Started around 18:00 UTC and was only at 19% when I looked at it just now at 16:20 UTC the following day. It must be noted that the scheduled run (which is still serial and untagged) started as scheduled around 01:00 UTC and started dealing with the same server. This resulted in double the deletion load. I have killed my manual tagged run to let the scheduled run take over and run its course at the normal deletion rate. (Grafana: mysql pc2007).
• pc2 (pc2008/pc1008): Started around 18:00 UTC and completed in 8 hours at 04:15 UTC. (Grafana: mysql pc2008).
• pc3 (pc2009/pc1009): Started around 18:00 UTC and completed in 17 hours at 11:22 UTC. (Grafana: mysql pc2009).

The wild difference in runtimes I think can be attributed to how the previous runs were cut-off and thus some servers having been idle/unpurged for a much longer time than others. pc2 is the one that I was manually purging in Eqiad, pc3 is the one that the scheduled run in Eqiad had almost finished purging, and pc1 has been waiting for its turn in the scheduled run with me only just getting started on it in Eqiad after also having been cut off in the previous runs.

Change 702425 had a related patch set uploaded (by Krinkle; author: Krinkle):

[operations/puppet@production] mediawiki: Run purgeParserCache.php in parallel for each shard

https://gerrit.wikimedia.org/r/702425

Change 702425 merged by Kormat:

[operations/puppet@production] mediawiki: Run purgeParserCache.php in parallel for each shard

https://gerrit.wikimedia.org/r/702425

Current status of the purge jobs after 14h:

• pc1: 32% done
• pc2: 31% done
• pc3: 100% done, but looks suspicious:

Jul  1 02:06:56 mwmaint2002 mediawiki_job_purge_parsercache_pc3[136034]: ... 33.2% done
Jul  1 02:07:08 mwmaint2002 mediawiki_job_purge_parsercache_pc3[136034]: ... 33.3% done
Jul  1 02:07:20 mwmaint2002 mediawiki_job_purge_parsercache_pc3[136034]: ... 100.0% done
Jul  1 02:07:20 mwmaint2002 mediawiki_job_purge_parsercache_pc3[136034]: Done

Could it be that the percentage calculation isn't taken the tag into account?

Otherwise pc1/pc2 are projected to take ~43h each in total.

And indeed:

Jul  1 09:44:18 mwmaint2002 mediawiki_job_purge_parsercache_pc1[196269]: ... 100.0% done
Jul  1 09:44:18 mwmaint2002 mediawiki_job_purge_parsercache_pc1[196269]: Done

Jul  1 09:59:10 mwmaint2002 mediawiki_job_purge_parsercache_pc2[196509]: ... 100.0% done
Jul  1 09:59:10 mwmaint2002 mediawiki_job_purge_parsercache_pc2[196509]: Done

Total run time for each section:

• pc1: 14.8h
• pc2: 15h
• pc3: 7.2h

Change 702729 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] objectcache: Fix progress printing to account for server tag filter

https://gerrit.wikimedia.org/r/702729

In the long run, with active-active multi-DC, the parsercache DELETEs should not be replicated, even if there is circular mysql replication at that time (it certainly would not be one way, either none or circular).

Since the running the purge script in only the primary DC would have some race conditions that would leave stuff in the secondary DC. For example, a key receives REPLACE in secondary DC B just after receiving a DELETE in primary DC A, the REPLACE does not replicate to A until a bit later, likewise with the DELETE replacating to B. The result is that the key only exists in A and will not be purged if a DC switchover happens first. Also, running the script in both DCs makes the DELETE replication pointless.

@Marostegui: It would be nice to expirement with non-replicated events using https://mariadb.com/kb/en/create-event/ . Any objection to enabling the event manager on pc* and x2 (DBMainStash) servers?

Change 702729 merged by jenkins-bot:

[mediawiki/core@master] objectcache: Fix SqlBagOStuff progress printing to account for server tags

https://gerrit.wikimedia.org/r/702729

So is this resolved? Runtime was less than 24 hours, right? Either it should be resolved or it should stop being UBN.

In T282761#7191214, @aaron wrote:

In the long run, with active-active multi-DC, the parsercache DELETEs should not be replicated, even if there is circular mysql replication at that time (it certainly would not be one way, either none or circular).

Since the running the purge script in only the primary DC would have some race conditions that would leave stuff in the secondary DC. For example, a key receives REPLACE in secondary DC B just after receiving a DELETE in primary DC A, the REPLACE does not replicate to A until a bit later, likewise with the DELETE replacating to B. The result is that the key only exists in A and will not be purged if a DC switchover happens first. Also, running the script in both DCs makes the DELETE replication pointless.

@Marostegui: It would be nice to expirement with non-replicated events using https://mariadb.com/kb/en/create-event/ . Any objection to enabling the event manager on pc* and x2 (DBMainStash) servers?

The event scheduler is ON by default in production (we use it for the query killers).
If this wants to be tested, I am ok with it, but I'd like to also explore other possibilities apart from events, as they can be a bottleneck in very loaded systems (we've seen this on Tendril and even with the query killers).

Current status:

• pc1: 26.7% (of 33.3%) done after 12.8h => est 16h total
• pc2: 22.3% (of 33.3%) done after 12.8h => est 19h total
• pc3: 33.3% (finished) after 3h17m total.

In T282761#7191906, @tstarling wrote:

So is this resolved? Runtime was less than 24 hours, right? Either it should be resolved or it should stop being UBN.

For the record, we decided in yesterday's meeting to keep monitoring this over the next 7 days since various circumstances make yesterday's and today's run less than representative (pc3 was handled manually shortly before, and all three were started 6h ahead of the regular schedule). Today's run will catch up with that, and tomorrow's run will (hopefully) be first "normal" clean day-over-day run since April last year.

Assuming all that remains within 24h, this can be closed, although I do note that we're currently still with reduced retention (30d->20d). When we increase under T280604, there'll be more data per-server and thus significantly more purging time again. Our hope is this will be balanced out by the newer hardware and proposed RAID configuration, but we can monitor all that under T280604.

Runtimes so far this week:

Monday 5th:
* pc1: 13h
* pc2: 15h
* pc3: 14h

Tuesday 6th:
* pc1: 11h
* pc2: 13h
* pc3: 12h

Just something I noticed on each run:

Jul  6 14:03:57 mwmaint2002 mediawiki_job_purge_parsercache_pc2[225981]: ... 33.2% done (+322 iterations in 142.9s)
Jul  6 14:06:21 mwmaint2002 mediawiki_job_purge_parsercache_pc2[225981]: ... 33.3% done (+318 iterations in 143.8s)
Jul  6 14:08:05 mwmaint2002 mediawiki_job_purge_parsercache_pc2[225981]: ... 100.0% done (+252 iterations in 104.8s)
Jul  6 14:08:05 mwmaint2002 mediawiki_job_purge_parsercache_pc2[225981]: Done

That big jump seems to happen on each run for each shard, is that normal?

Runtimes:

Wednesday 7th:
* pc1: 11h
* pc2: 13h
* pc3: 11h

In T282761#7200172, @Marostegui wrote:

Jul  6 14:06:21 mwmaint2002 mediawiki_job_purge_parsercache_pc2[225981]: ... 33.3% done (+318 iterations in 143.8s)
Jul  6 14:08:05 mwmaint2002 mediawiki_job_purge_parsercache_pc2[225981]: ... 100.0% done (+252 iterations in 104.8s)

That big jump seems to happen on each run for each shard, is that normal?

Kind of. It was a bug in the patch that added the --tag parameter. It still calculated as if it was purging all three, with a static 100% ensured as last printed progress line. Already fixed in https://gerrit.wikimedia.org/r/702729, which should roll out next week.

Excellent, thank you!

Friday 9th:
* pc1: 11h
* pc2: 12h
* pc3: 12h

These runtimes seem pretty stable lately, so I guess it is fine to close this as fixed?
Once we have the new hosts in place, that should also help.