Page MenuHomePhabricator

Mydumper incompatibility with MariaDB 10.6 (was: Logical recoveries (myloader) to db2098:s7 are failing with "Lock wait timeout exceeded; try restarting transaction")
Closed, ResolvedPublic

Description

Update: Debian package for bullseye (mydumper 0.10.0, built against MySQL 10.5.8) was tested to work until version 10.5. With 10.6, we believe we need a newer version for reloading of chunks due to a bug (currently validating 0.12.7-3)

Update 2: there seems to be a difference in formatting between 0.10 and 0.12, making impossible to load 0.10-generated dumps with 0.12.

Update 3: Thread-handling issues keep happening when loading 10.6 databases (it works with the higher version mydumper + 10.4) :-(

db2098 crashed recently (T318062), which led to temporarily substituting its backup generation service with another host. However, once the hardware memory issues were corrected, we would like to have db2098 as a passive redundant host for the database backup service.

In order to make sure data was safe, the host was re-imaged (with the same os release, bullseye) and tested with MariaDB 10.6, which is soon to be the preferred MariaDB version for MediaWiki, mostly to make sure the tooling was ready.

However, myloader fails (although it returns success) with several instances of:

** (myloader:2742004): CRITICAL **: 09:17:59.941: Error restoring fawiki.pagelinks from file fawiki.pagelinks.00001.sql.gz: Lo
ck wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:18:50.058: Error restoring fawiki.pagelinks from file fawiki.pagelinks.00002.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:19:00.358: Error restoring fawiki.pagelinks from file fawiki.pagelinks.00003.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:19:33.501: Error restoring fawiki.pagelinks from file fawiki.pagelinks.00004.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:24:05.014: Error restoring fawiki.templatelinks from file fawiki.templatelinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:24:55.159: Error restoring fawiki.templatelinks from file fawiki.templatelinks.00002.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:25:45.311: Error restoring fawiki.templatelinks from file fawiki.templatelinks.00003.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:26:26.140: Error restoring fawiki.templatelinks from file fawiki.templatelinks.00004.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:42:45.075: Error restoring cawiki.pagelinks from file cawiki.pagelinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:45:00.843: Error restoring cawiki.templatelinks from file cawiki.templatelinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 09:59:48.276: Error restoring arwiki.categorylinks from file arwiki.categorylinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

...

** (myloader:2742004): CRITICAL **: 18:57:26.804: Error restoring viwiki.slots from file viwiki.slots.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction  

** (myloader:2742004): CRITICAL **: 18:57:49.503: Error restoring viwiki.templatelinks from file viwiki.templatelinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 18:58:15.578: Error restoring viwiki.templatelinks from file viwiki.templatelinks.00002.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 18:58:16.927: Error restoring viwiki.templatelinks from file viwiki.templatelinks.00003.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 18:58:39.626: Error restoring viwiki.templatelinks from file viwiki.templatelinks.00004.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 18:59:06.995: Error restoring viwiki.text from file viwiki.text.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:2742004): CRITICAL **: 18:59:29.692: Error restoring viwiki.text from file viwiki.text.00002.sql.gz: Lock wait timeout exceeded; try restarting transaction

[The failures are real, load continues with many rows skipped/not reimported]

This makes no sense, as in theory mydumper loader makes sure to being able to restore table chunks in parallel (they are just independent inserts), and they should not block each other- in fact, we never had this issue until now. Possible reasons that could be affecting this issue:

  • Excessive locking due to configuration Discarded, it failed too after using: SET GLOBAL binlog_format=ROW; FLUSH LOGS; SET GLOBAL tx_isolation = 'READ-COMMITTED'; Note these hosts never had binlog enabled.
  • The particular dump is somehow corrupted Discarded, it failed with 2 different dumps, the second had for sure no concurrent alter tables or some other maintenance
  • 10.6 specific behavior (this was never tested before with 10.6, only with 10.4, as this was part of a first validation of this new version)
  • myloader bug - note that the behaviour of myloader is not ideal. https://bugs.launchpad.net/mydumper/+bug/806698 suggests to reduce --queries-per-transaction, but this wasn't necessary before (and it makes the loading slower). Better checking and monitoring may be needed anyway, because the behavior of the app is undesired
  • Config or other kind of regression on the wmf side (e.g. our tooling)
  • db2098 specific hardware or software configuration (eg. this being a multi-intance host that also serves s8 may be too small in io/memory resources to properly accommodate fast writes)

Event Timeline

jcrespo triaged this task as High priority.Oct 5 2022, 9:34 AM
jcrespo renamed this task from Logical recoveries (myloader) to db2098:s7 are failing with "Lock wait ti meout exceeded; try restarting transaction" to Logical recoveries (myloader) to db2098:s7 are failing with "Lock wait timeout exceeded; try restarting transaction".Oct 5 2022, 9:35 AM
jcrespo updated the task description. (Show Details)

I have news- not sure if good or bad - recovery to db2102.codfw.wmnet worked with 0 errors, and I will check now thoroughly, but most likely with no data loss. To me, this means that 10.6 has probably changed its behavior for myloader, however I have yet to prove that, as I also recovered to another host, with higher memory and IO, so it could be some of the other reasons- it if just a 10.6 regression (or myloader bug for that version) is now my top candidate. This also discards a bug on our workflow, and it means it is not a systemic issue on our WMF recovery workflow- so not an UBN.

The next test will be to try 10.4 on db2098- which will narrow more the issue.

As a note, this is happening for mydumper 0.10.0, built against MySQL 10.5.8. I wonder if I should try a higher version of 10.6 rather than a lower mariadb server version.

I built: mydumper 0.12.7-3, built against MySQL 10.5.15-MariaDB and will test a run of that on dbprov2002- hopefully this will not break ongoing backups or recoveries until I revert the upgrade before Monday night UTC.

my build of mydumper 0.12.7-3 didn't seem to work, with all threads fully idle:

root@db2098[(none)]> show processlist;
+-------+-----------------+--------------------+------+---------+--------+------------------------+------------------+------->
| Id    | User            | Host               | db   | Command | Time   | State                  | Info             | Progre>
+-------+-----------------+--------------------+------+---------+--------+------------------------+------------------+------->
|     1 | event_scheduler | localhost          | NULL | Daemon  | 191000 | Waiting on empty queue | NULL             |    0.0>
| 18579 | root            | 10.192.16.96:34130 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18580 | root            | 10.192.16.96:34132 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18581 | root            | 10.192.16.96:34134 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18582 | root            | 10.192.16.96:34136 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18583 | root            | 10.192.16.96:34138 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18584 | root            | 10.192.16.96:34142 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18585 | root            | 10.192.16.96:34158 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18586 | root            | 10.192.16.96:34170 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18587 | root            | 10.192.16.96:34180 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18588 | root            | 10.192.16.96:34184 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18589 | root            | 10.192.16.96:34186 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18590 | root            | 10.192.16.96:34200 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18591 | root            | 10.192.16.96:34210 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18592 | root            | 10.192.16.96:34220 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18593 | root            | 10.192.16.96:34224 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18594 | root            | 10.192.16.96:34230 | NULL | Sleep   |   1353 |                        | NULL             |    0.0>
| 18748 | root            | localhost          | NULL | Query   |      0 | starting               | show processlist |    0.0>
+-------+-----------------+--------------------+------+---------+--------+------------------------+------------------+------->
18 rows in set (0.000 sec)

Reverting package to the stable one.

Indeed- recovering to MariaDB 10.4 worked with no errors. MariaDB 10.6 makes the recovery fail- if this is because different configuration, mydumper not being compatible with MariaDB or something else (e.g. wmf options for myloader or the load not being generated with the same version), I don't know, but: recovery to 10.4 works consistently, and the same host with the same config on 10.6 fails with the above errors, making the upgrade the trigger.

I think this should inform the ongoing upgrade to 10.6, although not necessarily block it- challenges with mydumper support of mariadb are already showing up above- so it could also mean substituting the tooling with one more MariaDB-friendly.

jcrespo renamed this task from Logical recoveries (myloader) to db2098:s7 are failing with "Lock wait timeout exceeded; try restarting transaction" to Mydumper incompatibility with MariaDB 10.6 (was: Logical recoveries (myloader) to db2098:s7 are failing with "Lock wait timeout exceeded; try restarting transaction").Oct 10 2022, 8:50 AM

I was able to reproduce the issue on a simpler table with the 10.6 wmf package + mydumper 0.10.1-1; however, 0.12.7-3 fixes the issue (at least, if the dump is generated with the same version). This makes sense given that 0.10 is compiled with the 10.5 library.

I will now try the upstream package to restore a dump- maybe my compiled package (which was created quite fast and without proper testing) added existing debian patches that are now wrong or missing ones, e.g. missed requirements with thew new compression method.

Change 841116 had a related patch set uploaded (by Jcrespo; author: Jcrespo):

[operations/puppet@production] dbbackups: Upgrade db2102 to 10.6 to test myloader fix

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

Change 841116 merged by Jcrespo:

[operations/puppet@production] dbbackups: Upgrade db2102 to 10.6 to test myloader fix

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

This (T319383#8290794) doesn't seem to be a problem with my build, but an incompatibility between mydumper format between 0.10 and 0.12 versions, with is not great news. I am validating now creating a backup of a 10.4 and a 10.6 server with mydumper 0.12 and if both work we may want to start doing those with that (even current 10.4 servers), in preview of maximum compatibility.

Regular backups with the new (0.12) mydumper package worked nicely with MariaDB 10.4, too. I will have to validate the 2 server combinations for recovery, but I think the solution would be to upgrade mydumper- the new version generates additional files of per-table metadata, I believe to allow streaming backups.

Edit: While it may be working, the loading performance seems to not be great.

{F35562323}

Edit2: Loading causes thread issues, mydumper latest version has processes handling issues.

Thanks for all the updates Jaime, it was easy to get up to speed after holidays by reading your comments.
Anything I can help with?

There is one possibility with loading, and that is that the thread issues only happen because the wrapper now behaves strangely with a lot of output (e.g. progress bar tracking?). We can check reloading the dbs without the wrapper program to make sure it is not that, and that would simplify the issue a lot. If it is a second issue with MariaDB itself, the fix will be more difficult (maintain a backport of an unknow fix to a previous version or changing the loading process).

It didn't took long to create a prototype to load in the mydumper format:

1./mini_loader.sh /srv/backups/dumps/latest/dump.m2-scholarships.2022-11-29--10-13-38
2Creating database scholarships...
3ERROR 1007 (HY000) at line 1: Can't create database 'scholarships'; database exists
4Database scholarships failed to be created
5Creating table scholarships.iso_countries...
6Table scholarships.iso_countries created successfully
7Creating table scholarships.language_communities...
8Table scholarships.language_communities created successfully
9Creating table scholarships.rankings...
10Table scholarships.rankings created successfully
11Creating table scholarships.scholarships...
12Table scholarships.scholarships created successfully
13Creating table scholarships.settings...
14Table scholarships.settings created successfully
15Creating table scholarships.users...
16Table scholarships.users created successfully
17Importing data to table scholarships.iso_countries...
18Table scholarships.iso_countries imported successfully
19Importing data to table scholarships.language_communities...
20Table scholarships.language_communities imported successfully
21Importing data to table scholarships.settings...
22Table scholarships.settings imported successfully
23Importing data to table scholarships.users...
24Table scholarships.users imported successfully
25✔️
Parallelization is an xargs away.

It would be interesting to see the difference in length, in a sX section between that script and myloader. Just to have some rough idea...

It would be interesting to see the difference in length, in a sX section between that script and myloader. Just to have some rough idea...

Length in time? As in, performance optimized? Once parallelization is done we can can compare (but I don't expect a bash script to be faster than a proper C native-connector application, though).

It would be interesting to see the difference in length, in a sX section between that script and myloader. Just to have some rough idea...

Length in time? As in, performance optimized? Once parallelization is done we can can compare (but I don't expect a bash script to be faster than a proper C native-connector application, though).

Of course it won't be faster. What I am trying to say is compare and have some rough ideas on whether it is 2 days vs 2h or what.

I am running now a remote import test of a full m2 backup from a screen on dbprov1003 with 16 parallel threads into db1133:

root@db1133[(none)]> pager grep -c INSERT
PAGER set to 'grep -c INSERT'
root@db1133[(none)]> show processlist;
16
23 rows in set (0.000 sec)

Network write is ~40 MB/s, disk write is ~300 MiB/s: https://grafana.wikimedia.org/d/000000377/host-overview?orgId=1&var-server=db1133&var-datasource=thanos&var-cluster=mysql&from=1669825297000&to=1669849352000

Summary so far- I think this would be a good thing to have when flexibility would be needed and debugging. It could also solve some of the issue we have with lack of TLS support and other security concerns. However, making a good error handling won't be easy (it was not easy to do it for myloaded either- that is why metadata tracking and production recovery testing was needed). We'll see tomorrow about performance. Specially same-table loading.

Edit: One mistake I made is forgetting to disable the binary log, which is the bottleneck right now: https://grafana.wikimedia.org/goto/J3n9AIF4k?orgId=1

The current script is able to reload a dump of the Phabricator databases (434GB) in 12 hours ( https://grafana.wikimedia.org/d/000000273/mysql?orgId=1&var-job=All&var-server=db1133&var-port=9104&from=1669880505155&to=1669929579334) although all tables except a very tall one were imported in the first 1h15min, probably comparable in time to myloader due to limited table concurrency and that it had unaltered configuration and was still replicating s1:

root@dbprov1003:~$ ./mini_loader.sh /srv/backups/dumps/latest/dump.m3.2022-11-29--03-58-42/
Starting recovery at 2022-12-01 08:33:17+00:00
Creating database phabricator_almanac...
...
Importing data to table phabricator_repository.repository_commit_fngrams.00016...
Table phabricator_repository.repository_commit_fngrams.00016 imported successfully
Finishing recovery at 2022-12-01 20:09:32+00:00

I will now do a load comparison between both recovery methods on a more realistic scenario with an s* section with MariaDB 10.6, at the same time that I check definitively that the issue is either on myloader side or on mariadb server side.

Thanks for the update! Looking forward to seeing that next comparison

Change 863264 had a related patch set uploaded (by Jcrespo; author: Jcrespo):

[operations/software/wmfbackups@master] miniloader: Draft small utilitiy to load a mydumper dump in an emergency

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

s5 (a best case scenario, our smallest wiki section and a balanced number of tables) took 10h30 with the oneliners:

root@dbprov1003:~$ ./mini_loader.sh /srv/backups/dumps/latest/dump.s5.2022-11-29--00-00-02/
Starting recovery at 2022-12-02 12:57:56+00:00
Creating database amiwiki...
Database amiwiki created successfully
...
Table altwiki.slot_roles imported successfully
Finishing recovery at 2022-12-02 23:27:59+00:00
du -hs /srv/sqldata/ ~> 1.2T    /srv/sqldata/

Loading with mydumper 0.10 into 10.6.10 fails almost immediately:

root@db1133[(none)]> SELECT version(); ~> 10.6.10-MariaDB
$ myloader --version ~> myloader 0.10.0, built against MySQL 10.5.8
$ date ~> Sat 03 Dec 2022 08:03:39 AM UTC
$ /usr/bin/myloader --directory /srv/backups/dumps/latest/dump.s5.2022-11-29--00-00-02 --threads 16 --host db1133.eqiad.wmnet <credential options>
date

** (myloader:360924): CRITICAL **: 08:04:00.244: Error restoring cebwiki.externallinks from file cebwiki.externallinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:360924): CRITICAL **: 08:04:25.685: Error restoring cebwiki.pagelinks from file cebwiki.pagelinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

** (myloader:360924): CRITICAL **: 08:04:50.352: Error restoring cebwiki.pagelinks from file cebwiki.pagelinks.00002.sql.gz: Lock wait timeout exceeded; try restarting transaction

Note that the only failures happen due to lock waits while importing rows into the same table (numbered files), but it works when just using mysql command client, so it is the interaction between the tooling and the server version that has changed.

s5 (a best case scenario, our smallest wiki section and a balanced number of tables) took 10h30 with the oneliners:

Do you remember, more or less, how long it used to take with myloader?

Do you remember, more or less, how long it used to take with myloader?

I'd say around 12 hours or more. I did a small optimization by loading the largest files first so we don't end up with a long running thread of the revision table at the end, as mydumper uses I think alphabetical order. I can test on a 10.4 host + enwiki for a better comparison.

Ah cool, so the times are pretty similar, and there's not a big difference (for good or bad).

From the general log:

root@db1133[cebwiki]> SHOW CREATE TABLE externallinks;

CREATE TABLE `externallinks` (
  `el_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `el_from` int(8) unsigned NOT NULL DEFAULT 0,
  `el_to` blob NOT NULL,
  `el_index` blob NOT NULL,
  `el_index_60` varbinary(60) NOT NULL,
  `el_to_domain_index` varbinary(255) NOT NULL DEFAULT '',
  `el_to_path` blob DEFAULT NULL,
  PRIMARY KEY (`el_id`),
  KEY `el_to` (`el_to`(60),`el_from`),
  KEY `el_index` (`el_index`(60)),
  KEY `el_index_60` (`el_index_60`,`el_id`),
  KEY `el_from_index_60` (`el_from`,`el_index_60`,`el_id`),
  KEY `el_to_domain_index_to_path` (`el_to_domain_index`,`el_to_path`(60)),
  KEY `el_from` (`el_from`)
) ENGINE=InnoDB AUTO_INCREMENT=81440035 DEFAULT CHARSET=binary ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=8
221205 10:33:41     11 Connect  dump@10.64.32.26 on  using TCP/IP
                    11 Query    SET SESSION wait_timeout = 2147483
                    11 Query    SET SQL_LOG_BIN=0
                    11 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    12 Connect  dump@10.64.32.26 on  using TCP/IP
                    12 Query    SET SESSION wait_timeout = 2147483
                    12 Query    SET SQL_LOG_BIN=0
                    12 Query    /*!40101 SET NAMES binary*/
                    12 Query    /*!40101 SET SQL_MODE='NO_AUTO_VALUE_ON_ZERO' */
                    12 Query    /*!40014 SET UNIQUE_CHECKS=0 */
                    12 Query    SET autocommit=0


```... (15 more unique connections)
                  11 Query    SHOW CREATE DATABASE `avkwiki`
                  11 Query    CREATE DATABASE `avkwiki` /*!40100 DEFAULT CHARACTER SET binary */
                  11 Query    USE `avkwiki`
                  11 Query    /*!40101 SET NAMES binary*/
                  11 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                  11 Query    /*!40103 SET TIME_ZONE='+00:00' */
                  11 Query    CREATE TABLE `abuse_filter` (
`af_id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`af_pattern` blob NOT NULL,
`af_user` bigint(20) unsigned NOT NULL,
`af_user_text` varbinary(255) NOT NULL,
`af_timestamp` binary(14) NOT NULL,
`af_enabled` tinyint(1) NOT NULL DEFAULT 1,
`af_comments` blob DEFAULT NULL,
`af_public_comments` tinyblob DEFAULT NULL,
`af_hidden` tinyint(1) NOT NULL DEFAULT 0,
`af_hit_count` bigint(20) NOT NULL DEFAULT 0,
`af_throttled` tinyint(1) NOT NULL DEFAULT 0,
`af_deleted` tinyint(1) NOT NULL DEFAULT 0,
`af_actions` varbinary(255) NOT NULL DEFAULT '',
`af_global` tinyint(1) NOT NULL DEFAULT 0,
`af_group` varbinary(64) NOT NULL DEFAULT 'default',
PRIMARY KEY (`af_id`),
KEY `af_user` (`af_user`),
KEY `af_group_enabled` (`af_group`,`af_enabled`,`af_id`)

) ENGINE=InnoDB DEFAULT CHARSET=binary

... (all database and tables creations by thread 11)

                    16 Query    USE `apiportalwiki`
                    12 Query    USE `apiportalwiki`
                    21 Query    USE `apiportalwiki`
                    25 Query    USE `apiportalwiki`
                    24 Query    USE `apiportalwiki`
                    14 Query    USE `apiportalwiki`
                    13 Query    USE `apiportalwiki`
                    18 Query    USE `apiportalwiki`
                    26 Query    USE `apiportalwiki`
                    15 Query    USE `apiportalwiki`
                    19 Query    USE `apiportalwiki`
                    16 Query    START TRANSACTION
                    21 Query    START TRANSACTION
                    22 Query    USE `apiportalwiki`
                    23 Query    USE `apiportalwiki`
                    25 Query    START TRANSACTION
                    24 Query    START TRANSACTION
                    18 Query    START TRANSACTION
                    27 Query    USE `apiportalwiki`
                    26 Query    START TRANSACTION
                    20 Query    USE `apiportalwiki`
                    13 Query    START TRANSACTION
                    17 Query    USE `apiportalwiki`
                    14 Query    START TRANSACTION
                    21 Query    /*!40101 SET NAMES binary*/
                    19 Query    START TRANSACTION
                    15 Query    START TRANSACTION
                    22 Query    START TRANSACTION
                    21 Query    /*!40101 SET NAMES binary*/
                    19 Query    START TRANSACTION
                    15 Query    START TRANSACTION
                    22 Query    START TRANSACTION
                    16 Query    /*!40101 SET NAMES binary*/
                    23 Query    START TRANSACTION
                    20 Query    START TRANSACTION
                    27 Query    START TRANSACTION
                    17 Query    START TRANSACTION
                    12 Query    START TRANSACTION
                    21 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    24 Query    /*!40101 SET NAMES binary*/
                    13 Query    /*!40101 SET NAMES binary*/
                    14 Query    /*!40101 SET NAMES binary*/
                    16 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    18 Query    /*!40101 SET NAMES binary*/
                    19 Query    /*!40101 SET NAMES binary*/
                    21 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    13 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    25 Query    /*!40101 SET NAMES binary*/
                    22 Query    /*!40101 SET NAMES binary*/
                    17 Query    /*!40101 SET NAMES binary*/
                    15 Query    /*!40101 SET NAMES binary*/
                    27 Query    /*!40101 SET NAMES binary*/
                    19 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    18 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    23 Query    /*!40101 SET NAMES binary*/
                    16 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    26 Query    /*!40101 SET NAMES binary*/
                    20 Query    /*!40101 SET NAMES binary*/
                    21 Query    INSERT INTO `ipblocks` VALUES (<values omitted>)
                    13 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    14 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    25 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    22 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    24 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    27 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    17 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    15 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    19 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    26 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    14 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    12 Query    /*!40101 SET NAMES binary*/
                    13 Query    INSERT INTO `imagelinks` VALUES (<values omitted>)
                    16 Query    INSERT INTO `discussiontools_subscription` VALUES (<values omitted>)
                    18 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    20 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    23 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    22 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    26 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    19 Query    INSERT INTO `linter` VALUES (<values omitted>)

Continues for a total of 16 threads.

<values of insert omitted>)
                   21 Query    COMMIT
                   21 Query    USE `cebwiki`
                   21 Query    START TRANSACTION
                   21 Query    /*!40101 SET NAMES binary*/
                   21 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                   21 Query    /*!40103 SET TIME_ZONE='+00:00' */
                   22 Query    COMMIT

...

21 Query    INSERT INTO `actor` VALUES (<values omitted>

...

                     <insert values omitted>)
                    26 Query    COMMIT
                    26 Query    USE `cebwiki`
                    26 Query    START TRANSACTION
                    26 Query    /*!40101 SET NAMES binary*/
                    26 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    26 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    26 Query    INSERT INTO `externallinks` VALUES
(1, <values omitted>)

...

                    <previous insert>)
                    20 Query    COMMIT
                    20 Query    USE `cebwiki`
                    20 Query    START TRANSACTION
                    20 Query    /*!40101 SET NAMES binary*/
                    20 Query    /*!40014 SET FOREIGN_KEY_CHECKS=0*/
                    20 Query    /*!40103 SET TIME_ZONE='+00:00' */
                    20 Query    INSERT INTO `externallinks` VALUES
(40721136, 

                    26 Query    INSERT INTO `externallinks` VALUES
(13492,

                    26 Query    INSERT INTO `externallinks` VALUES
(31809,

First error [in client's output]: ** (myloader:789341): CRITICAL **: 10:34:47.996: Error restoring cebwiki.externallinks from file cebwiki.externallinks.00001.sql.gz: Lock wait timeout exceeded; try restarting transaction

I believe it is thread 20 that gets blocked. But I don't understand why, because it is inserting a separate set of rows, with different primary keys. Sure, the commits are held for long (autocommit=0), but the blocking shouldn't happen in the first place.

This comment was removed by jcrespo.

By changing the transaction size with:

/usr/bin/myloader --directory /srv/backups/dumps/latest/dump.s5.2022-11-29--00-00-02 --threads 16 --host db1133.eqiad.wmnet <credential options> -q 1

Import took from: 2022-12-05 15:21:00 to 2022-12-06 02:37:00

Based on the general log, starting with 10.6, inserting on a [empty] table locks the table for other writes, even if gap locking is not needed- causing a full table lock and a log of contention, leading to a wait timeout. The solution is to virtually disabling autocommit (by committing after each insert), with the potential reduction of performance implied. The issue is that the fix is not ideal- a full table lock disabling concurrent inserts is something that limits the concurrency a lot.

The import time was 11h16m

This is an interesting finding, maybe we need to pass this info along to Marko and see if they can guess why (and if it is expected) it happens.
Also interesting to see that the script is faster than this last run of myloader - good job! :)

This comment was removed by jcrespo.

So this task (not the root causes in MariaDB & mydumper) may be close to be finalized:

  1. 10.6 backup issues will be fixed by upgrading to 0.12, or a later version (whatever is the most stable).
  2. 10.6 recover issue will be fixed by virtually enabling autocommit (committing on every insert) or using the custom import script (despite being slower than it can be)
  3. MariaDB and mydumper will have to kept being monitored and constantly tested to check for contention issues and correctness on both backup and recover

Mentioned in SAL (#wikimedia-operations) [2023-03-01T08:26:07Z] <jynus> stopping db2184 for testing mariadb 10.6 recovery workflow T319383

Change 893400 had a related patch set uploaded (by Jcrespo; author: Jcrespo):

[operations/puppet@production] dbbackups: Implement myloader override in all hosts where it is installed

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

Change 893400 abandoned by Jcrespo:

[operations/puppet@production] dbbackups: Implement myloader override in all hosts where it is installed

Reason:

method doesn't fix the issue

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

Change 893803 had a related patch set uploaded (by Jcrespo; author: Jcrespo):

[operations/puppet@production] Moving the working prototype/hack into production

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

Change 893803 merged by Jcrespo:

[operations/puppet@production] dbbackups: Moving the recovery working prototype/hack into production

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

Change 893813 had a related patch set uploaded (by Jcrespo; author: Jcrespo):

[operations/puppet@production] dbbackups: Add parallel as a dependency of mini_loader.sh

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

Change 893813 merged by Jcrespo:

[operations/puppet@production] dbbackups: Add parallel as a dependency of mini_loader.sh

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

Change 863264 abandoned by Jcrespo:

[operations/software/wmfbackups@master] miniloader: Draft small utility to load a mydumper dump in an emergency

Reason:

The latest version is on puppet- will return to that at a later time.

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