What else is going on in the database?

In T110034#1570836, @Nemo_bis wrote:

What else is going on in the database?

https://wikitech.wikimedia.org/wiki/Incident_documentation/20150825-Redis ?

In T110034#1570836, @Nemo_bis wrote:

What else is going on in the database?

MariaDB [(none)]> show full processlist;
+--------+-----------+-------------------+-------------+---------+------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| Id     | User      | Host              | db          | Command | Time | State  | Info                                                                                                                                                                                                                                                                                                                                                              | Progress |
+--------+-----------+-------------------+-------------+---------+------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| 146694 | root      | localhost         | NULL        | Query   |    0 | init   | show full processlist                                                                                                                                                                                                                                                                                                                                             |    0.000 |
| 146745 | mediawiki | 185.52.1.75:38964 | delete3wiki | Sleep   |   37 |        | NULL                                                                                                                                                                                                                                                                                                                                                              |    0.000 |
| 146746 | mediawiki | 185.52.1.75:39184 | delete3wiki | Query   |   37 | update | INSERT /* User::addToDatabase  */ IGNORE INTO `user` (user_id,user_name,user_password,user_newpassword,user_newpass_time,user_email,user_email_authenticated,user_real_name,user_token,user_registration,user_editcount,user_touched) VALUES (NULL,'Southparkfan','','',NULL,'',NULL,'','[REDACTED]','20150825144634','0','20150825144639') |    0.000 |
+--------+-----------+-------------------+-------------+---------+------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+

In T110034#1570852, @Aklapper wrote:

In T110034#1570836, @Nemo_bis wrote:

What else is going on in the database?

https://wikitech.wikimedia.org/wiki/Incident_documentation/20150825-Redis ?

@Aklapper: Why do you post that link, do you think that incident is related (I don't think so - but perhaps that's not true...)?

In T110034#1571165, @Southparkfan wrote:

@Aklapper: Why do you post that link

Just a wild guess that might actually be unrelated. Sorry.

In T110034#1571165, @Southparkfan wrote:

In T110034#1570836, @Nemo_bis wrote:

What else is going on in the database?

MariaDB [(none)]> show full processlist;
+--------+-----------+-------------------+-------------+---------+------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| Id     | User      | Host              | db          | Command | Time | State  | Info                                                                                                                                                                                                                                                                                                                                                              | Progress |
+--------+-----------+-------------------+-------------+---------+------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| 146694 | root      | localhost         | NULL        | Query   |    0 | init   | show full processlist                                                                                                                                                                                                                                                                                                                                             |    0.000 |
| 146745 | mediawiki | 185.52.1.75:38964 | delete3wiki | Sleep   |   37 |        | NULL                                                                                                                                                                                                                                                                                                                                                              |    0.000 |
| 146746 | mediawiki | 185.52.1.75:39184 | delete3wiki | Query   |   37 | update | INSERT /* User::addToDatabase  */ IGNORE INTO `user` (user_id,user_name,user_password,user_newpassword,user_newpass_time,user_email,user_email_authenticated,user_real_name,user_token,user_registration,user_editcount,user_touched) VALUES (NULL,'Southparkfan','','',NULL,'',NULL,'','[REDACTED]','20150825144634','0','20150825144639') |    0.000 |
+--------+-----------+-------------------+-------------+---------+------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+

From https://dev.mysql.com/doc/refman/5.0/en/show-processlist.html :

Are you sure you're seeing all processes of the server?

I think (But not really sure, haven't tried it), that

SHOW ENGINE INNODB STATUS\G

can show information about which transactions have what locks. That might be useful.

Discard my comment about the PROCESS privilege, since it also shows the root user, which obviously has the right since is who's issuing the show full processlist command

Personally, It doesn't really seem possible that you could have deadlock when there is only 1 transaction going. What else could possibly be contending for access? (Although I'm not all that familiar with mysql locking)

Maybe something is messed with your mariadb install.

"Lock wait timeout exceeded" means that InnoDB could not lock the rows that have to be written (beforehand). Looking at your other process, it is clear that 146745 is the cause, even if it is not executing nothing right now it probably wrote to those table but didn't commit the changes, so it continues holding the changes. If you have a permission limitation, it could be other process, and both of those are blocked.

To clarify which processes have rows locked, use "SHOW ENGINE INNODB STATUS\G" on the server while the block is ongoing to understand the reason. Most of mediawiki, at least on WMF, assumes no gap locking, so READ COMMITTED or lower consistency level. I cannot assure that REPEATABLE READS with gap locking does not work, and it could be the cause (but only because that is not unit-tested), but that is something that I cannot say for sure without knowing your configuration. Check our production my.cnf innodb configuration for details.

Thanks for reopening I guess. Anyway, resolved by following a bit of @jcrespo's advice which can be seen in the commit.

I'm wondering if REPEATABLE READ is not working but READ COMMITTED is, should MediaWiki establish explicitly its transaction isolation level when making the connection instead of relying on the default one, to prevent errors like this?

For mediawiki devs: I would open an upstream bug to check if mediawiki works with the default MySQL isolation level, I cannot confirm that the bug is real unless we have more testing (it could be a race condition, and they just think that I helped them with confirmation bias :-P).

If someones has the time, it should be tested and either fix this particular script (preferred) or documented.

In T110034#1575727, @jcrespo wrote:

For mediawiki devs: I would open an upstream bug to check if mediawiki works with the default MySQL isolation level, I cannot confirm that the bug is real unless we have more testing (it could be a race condition, and they just think that I helped them with confirmation bias :-P).

If someones has the time, it should be tested and either fix this particular script (preferred) or documented.

My test wiki uses the default mysql "REPEATABLE READ" isolation level. I've never had deadlock issues (Of course, there's only 1 user using my wiki at a time, but the description of the problem above made it sound like there was only a single user, also my testwiki is not using central auth, but still, I find it hard to believe that the default value would cause large problems, when 90% of non-wmf wikis out there use it)

The processlist displays 2 processes, one idle and another performing the update, both from MediaWiki. I guess the script is opening 2 connections, the first one was to check if the user exists, and the other is to insert the user in the database.

I've tried that operation using 2 different connections with transactions and I haven't found any locking issue. The first select doesn't create a lock that prevents the insert from the second connection. Instead, it creates a snapshot, so performing the first select after the insert doesn't display the inserted row. I've tried REPEATABLE READ and SERIALIZABLE (for both connections) and no lock wait timeout happened...