MySQL 并发教程(四)
事务、案例研究:记录级锁
记录锁争用是最常遇到的,但通常也是最不具干扰性的,因为默认的锁等待超时只有 50 秒,所以不存在查询堆积的可能性。也就是说,在某些情况下——正如将要展示的那样——记录锁会导致 MySQL 嘎然而止。本章将从总体上研究 InnoDB 记录锁定问题,更详细地研究锁定等待超时问题。对死锁细节的研究将推迟到下一章。
症状
InnoDB 记录锁争用的症状通常非常微妙,不容易识别。在严重的情况下,您会得到锁等待超时或死锁错误,但在许多情况下,可能没有直接的症状。更确切地说,症状是查询比正常情况下慢。这可能从慢几分之一秒到慢很多秒不等。
对于存在锁等待超时的情况,您将看到类似于以下示例中的ER_LOCK_WAIT_TIMEOUT错误:
ERROR: 1205: Lock wait timeout exceeded; try restarting transaction
当查询比没有锁争用时要慢时,最有可能检测到问题的方法是通过监控,要么使用类似于 MySQL Enterprise Monitor 中的查询分析器,要么使用sys.innodb_lock_waits视图检测锁争用。图 15-1 显示了查询分析器中的一个查询示例。在讨论记录锁争用的调查时,将使用sys模式视图。该图在本书的 GitHub 知识库中以figure_15_1_quan.png的形式提供。
图 15-1
查询分析器中检测到的锁争用示例
在图中,请注意查询的延迟图是如何在接近周期结束时增加,然后又突然下降的。规范化查询的右侧还有一个红色图标,该图标表示查询返回了错误。在这种情况下,错误是锁等待超时,但是从图中看不到。规范化查询左侧的环形图还显示了一个红色区域,指示查询的查询响应时间索引 1 有时被认为很差。顶部的大图显示了一个小的下降,表明实例中有足够多的问题导致实例的性能普遍下降。
还有几个实例级指标显示实例发生了多少锁定。这对于监控一段时间内的一般锁争用非常有用。清单 15-1 使用sys.metrics视图显示了可用的指标。
mysql> SELECT Variable_name,
Variable_value AS Value,
Enabled
FROM sys.metrics
WHERE Variable_name LIKE 'innodb_row_lock%'
OR Type = 'InnoDB Metrics - lock';
+-------------------------------+--------+---------+
| Variable_name | Value | Enabled |
+-------------------------------+--------+---------+
| innodb_row_lock_current_waits | 0 | YES |
| innodb_row_lock_time | 480628 | YES |
| innodb_row_lock_time_avg | 1219 | YES |
| innodb_row_lock_time_max | 51066 | YES |
| innodb_row_lock_waits | 394 | YES |
| lock_deadlock_false_positives | 0 | YES |
| lock_deadlock_rounds | 193790 | YES |
| lock_deadlocks | 0 | YES |
| lock_rec_grant_attempts | 218 | YES |
| lock_rec_lock_created | 0 | NO |
| lock_rec_lock_removed | 0 | NO |
| lock_rec_lock_requests | 0 | NO |
| lock_rec_lock_waits | 0 | NO |
| lock_rec_locks | 0 | NO |
| lock_rec_release_attempts | 7522 | YES |
| lock_row_lock_current_waits | 0 | YES |
| lock_schedule_refreshes | 193790 | YES |
| lock_table_lock_created | 0 | NO |
| lock_table_lock_removed | 0 | NO |
| lock_table_lock_waits | 0 | NO |
| lock_table_locks | 0 | NO |
| lock_threads_waiting | 0 | YES |
| lock_timeouts | 193 | YES |
+-------------------------------+--------+---------+
23 rows in set (0.0089 sec)
Listing 15-1InnoDB lock metrics
对于这个讨论,innodb_row_lock_%和lock_timeouts指标是最有趣的。三个时间变量以毫秒为单位。可以看到有 193 个锁等待超时,这本身并不一定是一个问题(至少您需要考虑这些超时发生了多长时间)。您还可以看到有 394 次锁不能被立即授予(innodb_row_lock_waits)并且等待时间超过 51 秒(innodb_row_lock_time_max)。当锁争用的总体水平增加时,您将看到这些指标也在增加。
甚至比手动监控指标更好的是,确保您的监控解决方案记录指标,并可以在时间序列图中绘制它们。图 15-2 显示了为图 15-1 中发现的同一事件绘制的指标示例。
图 15-2
InnoDB 行锁指标的时间序列图
图表显示了锁定的总体增加。锁等待的数量有两个阶段,随着锁等待的增加,然后再次下降。行锁定时间图显示了类似的模式。这是间歇性锁定问题的典型迹象。
原因
InnoDB 在行数据、索引记录、间隙和插入意图锁上使用共享锁和排他锁。当有两个事务试图以冲突的方式访问数据时,一个查询将不得不等待,直到所需的锁可用。简而言之,可以同时允许两个对共享锁的请求,但是一旦有了独占锁,任何连接都不能在同一个记录上获得锁。
由于排他锁最有可能导致锁争用,因此通常 DML 查询会更改导致 InnoDB 记录锁争用的数据。另一个来源是SELECT语句通过添加FOR SHARE(或LOCK IN SHARE MODE或FOR UPDATE子句来进行抢先锁定。
设置
这个示例只需要两个连接来设置正在研究的场景,第一个连接有一个正在进行的事务,第二个连接试图更新第一个连接持有锁的行。因为等待 InnoDB 锁的默认超时是 50 秒,所以您可以选择增加第二个连接的超时时间,这将会阻塞,以便您有更多的时间来执行调查。设置如清单 15-2 所示。
-- Connection Processlist ID Thread ID Event ID
-- --------------------------------------------------
-- 1 738 1219 6
-- 2 739 1220 6
-- Connection 1
Connection 1> START TRANSACTION;
Query OK, 0 rows affected (0.0002 sec)
Connection 1> UPDATE world.city
SET Population = 5000000
WHERE ID = 130;
Query OK, 1 row affected (0.0248 sec)
Rows matched: 1 Changed: 1 Warnings: 0
-- Connection 2
Connection 2> SET SESSION innodb_lock_wait_timeout = 3600;
Query OK, 0 rows affected (0.0004 sec)
Connection 2> START TRANSACTION;
Query OK, 0 rows affected (0.0002 sec)
Connection 2> UPDATE world.city SET Population = Population * 1.10 WHERE CountryCode = 'AUS';
Listing 15-2Triggering InnoDB record lock contention
在本例中,连接 2 的锁等待超时设置为 3600 秒,以便您有一个小时的时间来调查问题。Connection 2 的START TRANSACTION不是必需的,但是允许您在完成后回滚两个事务,以避免对数据进行更改。
调查
调查记录锁与调查元数据锁非常相似。您可以查询性能模式中的data_locks和data_lock_waits表,它们将分别显示原始锁数据和挂起的锁。还有一个sys.innodb_lock_waits视图,它查询两个表来寻找一个被另一个阻塞的锁对。
Note
MySQL 8 中新增了data_locks和data_lock_waits表。在 MySQL 5.7 和更早的版本中,信息模式中有两个相似的表,分别名为INNODB_LOCKS和INNODB_LOCK_WAITS。使用innodb_lock_waits视图的一个优点是它在不同的 MySQL 版本上工作是一样的(但是在 MySQL 8 中有一些额外的信息)。
在大多数情况下,使用innodb_lock_waits视图开始调查是最容易的,并且只在需要时深入性能模式表。清单 15-3 显示了锁等待情况下innodb_lock_waits的输出示例。
-- Investigation #1
-- Connection 3
Connection 3> SELECT * FROM sys.innodb_lock_waits\G
*************************** 1\. row ***************************
wait_started: 2020-08-07 18:04:56
wait_age: 00:00:16
wait_age_secs: 16
locked_table: `world`.`city`
locked_table_schema: world
locked_table_name: city
locked_table_partition: NULL
locked_table_subpartition: NULL
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 537516
waiting_trx_started: 2020-08-07 18:04:56
waiting_trx_age: 00:00:16
waiting_trx_rows_locked: 2
waiting_trx_rows_modified: 0
waiting_pid: 739
waiting_query: UPDATE world.city SET Populati ... 1.10 WHERE CountryCode = 'AUS'
waiting_lock_id: 2711671601760:1923:7:44:2711634704240
waiting_lock_mode: X,REC_NOT_GAP
blocking_trx_id: 537515
blocking_pid: 738
blocking_query: NULL
blocking_lock_id: 2711671600928:1923:7:44:2711634698920
blocking_lock_mode: X,REC_NOT_GAP
blocking_trx_started: 2020-08-07 18:04:56
blocking_trx_age: 00:00:16
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 1
sql_kill_blocking_query: KILL QUERY 738
sql_kill_blocking_connection: KILL 738
1 row in set (0.0805 sec)
Listing 15-3Retrieving lock information from the innodb_lock_waits view
根据列名的前缀,输出中的列可以分为五个部分。这些群体是
-
wait_: 这些列显示了关于锁等待时间的一些一般信息。 -
locked_: 这些列显示了从模式到索引以及锁类型的锁。 -
waiting_: 这些列显示等待授予锁的事务的详细信息,包括查询和请求的锁模式。 -
blocking_: 这些列显示阻塞锁请求的事务的详细信息。注意,在这个例子中,阻塞查询是NULL。这意味着在生成输出时事务是空闲的。即使列出了阻塞查询,该查询也可能与存在争用的锁没有任何关系——除了该查询是由持有锁的同一事务执行的。 -
sql_kill_: 这两列提供了可用于终止阻塞查询或连接的KILL查询。
Note
列blocking_query是阻塞事务当前执行的查询(如果有的话)。这并不意味着查询本身必然会导致锁请求阻塞。
blocking_query列为NULL的情况是常见情况。这意味着阻塞事务当前没有执行查询。这可能是因为它在两个查询之间。如果这段时间很长,则表明应用正在做理想情况下应该在事务之外完成的工作。更常见的情况是,事务没有执行查询,因为它被遗忘了,要么是在交互会话中,人们忘记了结束事务,要么是在应用流中,不能确保事务被提交或回滚。
解决方案
解决方案取决于锁等待的程度。如果有几个查询的锁等待时间很短,那么让受影响的查询等待锁变得可用也是可以接受的。请记住,锁是为了确保数据的完整性,所以锁本身不是问题。只有当锁对性能造成重大影响或者导致查询失败到无法重试的程度时,锁才会成为问题。
如果锁定情况持续很长时间——特别是如果阻塞事务已经被放弃——您可以考虑终止阻塞事务。和往常一样,如果阻塞事务执行了大量工作,您需要考虑回滚可能会花费大量时间。
对于由于锁等待超时错误而失败的查询,应用应该重试它们。请记住,默认情况下,锁等待超时仅回滚超时发生时正在执行的查询。事务的其余部分与查询前一样。因此,处理超时失败可能会使未完成的事务带有自己的锁,这可能会导致进一步的锁问题。是只回滚查询还是回滚整个事务由innodb_rollback_on_timeout选项控制。
Caution
处理锁等待超时是非常重要的,否则它可能会使事务带有未释放的锁。如果发生这种情况,其他事务可能无法获得它们需要的锁。
预防
防止重大的记录级锁争用主要遵循第 9 章“减少锁定问题”中讨论的指导方针概括一下讨论,减少锁等待争用的方法主要是减少事务的大小和持续时间,使用索引来减少被访问的记录的数量,并可能将事务隔离级别切换到READ COMMITTED来更早地释放锁并减少间隙锁的数量。
摘要
在本章中,我们讨论了一个关于 InnoDB 记录锁的案例研究。症状是,一个本应很快的查询需要很长时间才能完成。确定锁争用中涉及哪些连接的关键是使用sys.innodb_lock_waits视图,该视图直接显示等待和阻塞连接的信息。要了解更多细节,您可以深入到性能模式中的data_locks和data_lock_waits表中。
解决方案取决于锁等待的程度。如果它们很短且不频繁,您可以忽略它们,让等待的查询等待锁请求变得可用。如果锁等待是由运行时间过长的查询或被遗忘的事务引起的,您可能需要终止有问题的查询或连接,但要考虑回滚更改。为了防止将来出现这种问题,请努力减少事务的大小和持续时间,检查索引,并考虑READ COMMITTED事务隔离级别。
在下一个案例研究中,将研究一个相关的问题,其中两个事务有一个循环锁等待图——通常称为死锁。
Footnotes [1](#Fn1_source)https://dev.mysql.com/doc/mysql-monitor/en/mem-features-qrti.html
十六、案例研究:死锁
数据库管理员最担心的锁问题之一是死锁。这一部分是因为它的名字,另一部分是因为它们不像讨论的其他锁问题那样总是会导致错误。然而,与其他锁定问题相比,没有什么特别担心死锁的。相反,它们导致错误意味着您能更快地知道它们,并且锁问题会自行解决。
本章设置了一个死锁场景,并完成了一项调查,以从 InnoDB monitor 输出中的死锁信息反向工作,从而确定死锁中涉及的事务。
症状
症状很明显。死锁的受害者接收到一个错误,并且lock_deadlocks InnoDB 度量增加。将返回给 InnoDB 选择作为受害者的事务的错误是ER_LOCK_DEADLOCK:
ERROR: 1213: Deadlock found when trying to get lock; try restarting transaction
这个指标对于观察死锁发生的频率非常有用。跟踪lock_deadlocks的值的一种简便方法是使用sys.metrics视图:
mysql> SELECT *
FROM sys.metrics
WHERE Variable_name = 'lock_deadlocks'\G
*************************** 1\. row ***************************
Variable_name: lock_deadlocks
Variable_value: 2
Type: InnoDB Metrics - lock
Enabled: YES
1 row in set (0.0096 sec)
或者,您可以使用性能模式中的events_errors_summary_global_by_error表并查询ER_LOCK_DEADLOCK错误:
mysql> SELECT *
FROM performance_schema.events_errors_summary_global_by_error
WHERE error_name = 'ER_LOCK_DEADLOCK'\G
*************************** 1\. row ***************************
ERROR_NUMBER: 1213
ERROR_NAME: ER_LOCK_DEADLOCK
SQL_STATE: 40001
SUM_ERROR_RAISED: 5
SUM_ERROR_HANDLED: 0
FIRST_SEEN: 2020-08-01 13:09:29
LAST_SEEN: 2020-08-07 18:28:20
1 row in set (0.0083 sec)
但是请注意,这包括所有返回错误 1213 的死锁情况,而不考虑锁的类型,而lock_deadlocks指标只包括 InnoDB 死锁。
您还可以检查 InnoDB 监控器输出中的LATEST DETECTED DEADLOCK部分,例如,通过执行SHOW ENGINE INNODB STATUS。这将显示上一次死锁发生的时间,因此您可以使用它来判断死锁发生的频率。如果您启用了innodb_print_all_deadlocks选项,错误锁将有许多死锁信息的输出。在讨论了死锁的原因和设置之后,“调查”一节将详细介绍死锁的 InnoDB 监控器输出。
原因
死锁是由两个或多个事务以不同的顺序获得锁引起的。每个事务最终都持有另一个事务需要的锁。该锁可以是记录锁、间隙锁、谓词锁或插入意图锁。图 16-1 显示了一个触发死锁的循环依赖的例子。
图 16-1
触发死锁的循环锁依赖关系
图中显示的死锁是由于表主键上的两个记录锁造成的。这是可能发生的最简单的死锁之一。如图所示,在调查死锁时,循环可能比这更复杂。
设置
这个例子使用了两个连接作为上一章的例子,但是这一次两个连接都在连接 1 阻塞之前进行了更改,直到连接 2 错误地回滚其更改。连接 1 用 10%更新澳大利亚及其城市的人口,而连接 2 用达尔文市的人口更新澳大利亚人口并添加城市。这些语句如清单 16-1 所示。
-- Connection Processlist ID Thread ID Event ID
-- --------------------------------------------------
-- 1 762 1258 6
-- 2 763 1259 6
-- Connection 1
Connection 1> START TRANSACTION;
Query OK, 0 rows affected (0.0005 sec)
Connection 1> UPDATE world.city SET Population = Population * 1.10 WHERE CountryCode = 'AUS';
Query OK, 14 rows affected (0.0016 sec)
Rows matched: 14 Changed: 14 Warnings: 0
-- Connection 2
Connection 2> START TRANSACTION;
Query OK, 0 rows affected (0.0005 sec)
Connection 2> UPDATE world.country SET Population = Population + 146000 WHERE Code = 'AUS';
Query OK, 1 row affected (0.2683 sec)
Rows matched: 1 Changed: 1 Warnings: 0
-- Connection 1
Connection 1> UPDATE world.country SET Population = Population * 1.10 WHERE Code = 'AUS';
-- Connection 2
Connection 2> INSERT INTO world.city VALUES (4080, 'Darwin', 'AUS', 'Northern Territory', 146000);
ERROR: 1213: Deadlock found when trying to get lock; try restarting transaction
-- Connection 1
Query OK, 1 row affected (0.1021 sec)
Rows matched: 1 Changed: 1 Warnings: 0
-- Connection 2
Connection 2> ROLLBACK;
Query OK, 0 rows affected (0.0003 sec)
-- Connection 1
Connection 1> ROLLBACK;
Query OK, 0 rows affected (0.0545 sec)
Listing 16-1Triggering an InnoDB deadlock
关键是这两个事务更新了city和country表,但是顺序相反。设置通过显式回滚这两个事务来完成,以确保表保持不变。
调查
分析死锁的主要工具是 InnoDB monitor 输出中有关最新检测到的死锁的信息部分。如果您启用了innodb_print_all_deadlocks选项(默认情况下为OFF,您还可以从错误日志中获得死锁信息;然而,信息是相同的,因此它不改变分析。
死锁信息包含描述死锁和结果的四个部分。这些零件是
-
当死锁发生时。
-
死锁中涉及的第一个事务的信息。
-
死锁所涉及的第二个事务的信息。
-
哪个事务被回滚。当
innodb_print_all_deadlocks启用时,该信息不包括在错误日志中。
两个事务的编号是任意的,主要目的是能够引用一个事务或另一个事务。包含事务信息的两个部分是最重要的部分。它们包括事务处于活动状态的时间长度、关于事务大小的一些统计信息(根据所使用的锁和撤销日志条目等)、正在阻塞等待锁的查询,以及关于死锁中所涉及的锁的信息。
锁信息不像使用data_locks和data_lock_waits表以及sys.innodb_lock_waits视图时那么容易解释。然而,一旦你尝试进行几次分析,这并不太难。
Tip
在测试系统中故意创建一些死锁,并研究由此产生的死锁信息。然后通过信息来确定死锁发生的原因。因为您知道查询,所以更容易解释锁数据。
对于这个死锁调查,考虑清单 16-2 中显示的 InnoDB 监控器的死锁部分。清单相当长,行也很宽,所以信息也可以在本书的 GitHub 存储库中作为listing_16_2_deadlock.txt获得,所以您可以在自己选择的文本编辑器中打开输出。
-- Investigation #1
-- Connection 3
Connection 3> SHOW ENGINE INNODB STATUS\G
*************************** 1\. row ***************************
...
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-08-07 20:08:55 0x9f0
*** (1) TRANSACTION:
TRANSACTION 537544, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 6 lock struct(s), heap size 1136, 30 row lock(s), undo log entries 14
MySQL thread id 762, OS thread handle 10344, query id 3282590 localhost ::1 root updating
UPDATE world.country SET Population = Population * 1.10 WHERE Code = 'AUS'
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 1923 page no 14 n bits 1272 index CountryCode of table `world`.`city` trx id 537544 lock_mode X locks gap before rec
Record lock, heap no 603 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 3; hex 415554; asc AUT;;
1: len 4; hex 800005f3; asc ;;
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1924 page no 5 n bits 120 index PRIMARY of table `world`.`country` trx id 537544 lock_mode X locks rec but not gap waiting
Record lock, heap no 16 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
0: len 3; hex 415553; asc AUS;;
1: len 6; hex 0000000833c9; asc 3 ;;
2: len 7; hex 02000001750a3c; asc u <;;
3: len 30; hex 4175737472616c6961202020202020202020202020202020202020202020; asc Australia ; (total 52 bytes);
4: len 1; hex 05; asc ;;
5: len 26; hex 4175737472616c696120616e64204e6577205a65616c616e6420; asc Australia and New Zealand ;;
6: len 5; hex 80761f2400; asc v $ ;;
7: len 2; hex 876d; asc m;;
8: len 4; hex 812267c0; asc "g ;;
9: len 2; hex cf08; asc ;;
10: len 5; hex 80055bce00; asc [ ;;
11: len 5; hex 8005fecf00; asc ;;
12: len 30; hex 4175737472616c6961202020202020202020202020202020202020202020; asc Australia ; (total 45 bytes);
13: len 30; hex 436f6e737469747574696f6e616c204d6f6e61726368792c204665646572; asc Constitutional Monarchy, Feder; (total 45 bytes);
14: len 30; hex 456c69736162657468204949202020202020202020202020202020202020; asc Elisabeth II ; (total 60 bytes);
15: len 4; hex 80000087; asc ;;
16: len 2; hex 4155; asc AU;;
*** (2) TRANSACTION:
TRANSACTION 537545, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
MySQL thread id 763, OS thread handle 37872, query id 3282591 localhost ::1 root update
INSERT INTO world.city VALUES (4080, 'Darwin', 'AUS', 'Northern Territory', 146000)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1924 page no 5 n bits 120 index PRIMARY of table `world`.`country` trx id 537545 lock_mode X locks rec but not gap
Record lock, heap no 16 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
0: len 3; hex 415553; asc AUS;;
1: len 6; hex 0000000833c9; asc 3 ;;
2: len 7; hex 02000001750a3c; asc u <;;
3: len 30; hex 4175737472616c6961202020202020202020202020202020202020202020; asc Australia ; (total 52 bytes);
4: len 1; hex 05; asc ;;
5: len 26; hex 4175737472616c696120616e64204e6577205a65616c616e6420; asc Australia and New Zealand ;;
6: len 5; hex 80761f2400; asc v $ ;;
7: len 2; hex 876d; asc m;;
8: len 4; hex 812267c0; asc "g ;;
9: len 2; hex cf08; asc ;;
10: len 5; hex 80055bce00; asc [ ;;
11: len 5; hex 8005fecf00; asc ;;
12: len 30; hex 4175737472616c6961202020202020202020202020202020202020202020; asc Australia ; (total 45 bytes);
13: len 30; hex 436f6e737469747574696f6e616c204d6f6e61726368792c204665646572; asc Constitutional Monarchy, Feder; (total 45 bytes);
14: len 30; hex 456c69736162657468204949202020202020202020202020202020202020; asc Elisabeth II ; (total 60 bytes);
15: len 4; hex 80000087; asc ;;
16: len 2; hex 4155; asc AU;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1923 page no 14 n bits 1272 index CountryCode of table `world`.`city` trx id 537545 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 603 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 3; hex 415554; asc AUT;;
1: len 4; hex 800005f3; asc ;;
*** WE ROLL BACK TRANSACTION (2)
Listing 16-2Example of the information for a detected deadlock
死锁发生在 2020 年 8 月 7 日,服务器时区 20:08:55。您可以使用此信息来查看该信息是否与用户报告的死锁相同。
有趣的部分是两个事务的信息。您可以看到,事务 1 正在用Code = 'AUS'更新国家的人口:
UPDATE world.country SET Population = Population * 1.10 WHERE Code = 'AUS'
事务 2 试图插入一个新的城市:
INSERT INTO world.city VALUES (4080, 'Darwin', 'AUS', 'Northern Territory', 146000)
这是一个死锁涉及多个表的情况。虽然这两个查询在不同的表上工作,但它本身并不能证明涉及到更多的查询,因为外键可以触发一个查询在两个表上获取锁。不过在本例中,Code列是country表的主键,唯一涉及的外键是从city表的CountryCode列到country表的Code列(显示这是留给使用world示例数据库的读者的一个练习)。所以两个查询不太可能自己死锁。
Note
在 MySQL 8.0.17 和更早的版本中,死锁信息包含的有关锁的信息更少。如果您仍在使用早期版本,升级将使调查死锁变得更加容易。
接下来要观察的是正在等待什么锁。事务 1 等待对country表的主键的排他锁:
RECORD LOCKS space id 1924 page no 5 n bits 120 index PRIMARY of table `world`.`country` trx id 537544 lock_mode X locks rec but not gap waiting
主键的值可以在该信息后面的信息中找到。由于 InnoDB 包含了与记录相关的所有信息,这看起来有点让人不知所措。因为它是主键记录,所以包含整行。这有助于理解行中的数据,特别是如果主键本身不包含这些信息,但是当您第一次看到它时,可能会感到困惑。country表的主键是表的第一列,所以它是记录信息的第一行,包含锁请求的主键的值:
0: len 3; hex 415553; asc AUS;;
InnoDB 以十六进制表示法包含该值,但也试图将其解码为一个字符串,因此这里很明显该值是“AUS”,这并不奇怪,因为它也在查询的WHERE子句中。这并不总是那么明显,所以您应该总是确认锁输出的值。您还可以从信息中看到,该列在索引中是按升序排序的。
事务 2 等待对city表的CountryCode索引的插入意图锁:
RECORD LOCKS space id 1923 page no 14 n bits 1272 index CountryCode of table `world`.`city` trx id 537545 lock_mode X locks gap before rec insert intention waiting
您可以看到锁定请求在记录之前包含一个间隙。在这种情况下,锁信息更简单,因为CountryCode索引中只有两列,即CountryCode列和主键(ID列),因为CountryCode索引是非唯一的二级索引。指标有效(CountryCode、ID),记录前间隙值如下:
0: len 3; hex 415554; asc AUT;;
1: len 4; hex 800005f3; asc ;;
这表明CountryCode的值是“AUT ”,这并不奇怪,因为当按字母升序排序时,它是“AUS”之后的下一个值。ID列的值是十六进制值 0x5f3,十进制值是 1523。如果您查询带有CountryCode = AUT的城市,并按照CountryCode索引的顺序对它们进行排序,您可以看到ID = 1523是找到的第一个城市:
-- Investigation #3
Connection 3> SELECT *
FROM world.city
WHERE CountryCode = 'AUT'
ORDER BY CountryCode, ID
LIMIT 1;
+------+------+-------------+----------+------------+
| ID | Name | CountryCode | District | Population |
+------+------+-------------+----------+------------+
| 1523 | Wien | AUT | Wien | 1608144 |
+------+------+-------------+----------+------------+
1 row in set (0.2673 sec)
目前为止,一切顺利。因为事务正在等待这些锁,所以当然可以推断出另一个事务持有锁。在 8.0.18 及更高版本中,InnoDB 包含了两个事务持有的锁的完整列表;在早期版本中,InnoDB 只为其中一个事务显式地包含这个查询,所以您需要确定事务还执行了哪些其他查询。
根据现有的信息,你可以做出一些有根据的猜测。例如,INSERT语句被CountryCode索引上的间隙锁阻塞。使用条件CountryCode = 'AUS'的查询就是一个使用该间隙锁的查询示例。死锁信息还包括关于拥有事务的两个连接的信息,这些信息可能对您有所帮助:
MySQL thread id 762, OS thread handle 10344, query id 3282590 localhost ::1 root updating
MySQL thread id 763, OS thread handle 37872, query id 3282591 localhost ::1 root update
您可以看到这两个连接都是使用root@localhost帐户建立的。如果您确保每个应用和角色有不同的用户,该帐户可以帮助您缩小执行事务的用户范围。
如果连接仍然存在,您还可以使用性能模式中的events_statements_history表来查找连接执行的最新查询。这可能不是死锁所涉及的那些人,这取决于该连接是否被用于更多的查询,但是仍然可以提供该连接用途的线索。如果连接不再存在,原则上您可以在events_statements_history_long表中找到查询,但是您需要将“MySQL 线程 id”(连接 ID)映射到 Performance Schema 线程 ID,这是很难做到的。另外,events_statements_history_long消费者在默认情况下是不启用的。
在这种特殊情况下,两个连接仍然存在,除了回滚事务之外,它们没有做任何事情。清单 16-3 展示了如何找到事务中涉及的查询。请注意,在实际情况下,查询可能会返回比这里显示的更多的行,因为不可能在event_id上添加过滤器。
-- Investigation #4
Connection 3> SELECT sql_text, nesting_event_id,
nesting_event_type, mysql_errno,
IFNULL(error_name, '') AS error,
message_text
FROM performance_schema.events_statements_history
LEFT OUTER JOIN performance_schema.events_errors_summary_global_by_error
ON error_number = mysql_errno
WHERE thread_id = PS_THREAD_ID(762)
AND event_id > 6
ORDER BY event_id\G
*************************** 1\. row ***************************
sql_text: start transaction
nesting_event_id: NULL
nesting_event_type: NULL
mysql_errno: 0
error:
message_text: NULL
*************************** 2\. row ***************************
sql_text: UPDATE world.city SET Population = Population * 1.10 WHERE CountryCode = 'AUS'
nesting_event_id: 8
nesting_event_type: TRANSACTION
mysql_errno: 0
error:
message_text: Rows matched: 14 Changed: 14 Warnings: 0
*************************** 3\. row ***************************
sql_text: UPDATE world.country SET Population = Population * 1.10 WHERE Code = 'AUS'
nesting_event_id: 8
nesting_event_type: TRANSACTION
mysql_errno: 0
error:
message_text: Rows matched: 1 Changed: 1 Warnings: 0
*************************** 4\. row ***************************
sql_text: rollback
nesting_event_id: 8
nesting_event_type: TRANSACTION
mysql_errno: 0
error:
message_text: NULL
4 rows in set (0.0016 sec)
-- Investigation #5
Connection 3> SELECT sql_text, nesting_event_id,
nesting_event_type, mysql_errno,
IFNULL(error_name, '') AS error,
message_text
FROM performance_schema.events_statements_history
LEFT OUTER JOIN performance_schema.events_errors_summary_global_by_error
ON error_number = mysql_errno
WHERE thread_id = PS_THREAD_ID(763)
AND event_id > 6
ORDER BY event_id\G
*************************** 1\. row ***************************
sql_text: start transaction
nesting_event_id: NULL
nesting_event_type: NULL
mysql_errno: 0
error:
message_text: NULL
*************************** 2\. row ***************************
sql_text: UPDATE world.country SET Population = Population + 146000 WHERE Code = 'AUS'
nesting_event_id: 8
nesting_event_type: TRANSACTION
mysql_errno: 0
error:
message_text: Rows matched: 1 Changed: 1 Warnings: 0
*************************** 3\. row ***************************
sql_text: INSERT INTO world.city VALUES (4080, 'Darwin', 'AUS', 'Northern Territory', 146000)
nesting_event_id: 8
nesting_event_type: TRANSACTION
mysql_errno: 1213
error: ER_LOCK_DEADLOCK
message_text: Deadlock found when trying to get lock; try restarting transaction
*************************** 4\. row ***************************
sql_text: SHOW WARNINGS
nesting_event_id: NULL
nesting_event_type: NULL
mysql_errno: 0
error:
message_text: NULL
*************************** 5\. row ***************************
sql_text: rollback
nesting_event_id: NULL
nesting_event_type: NULL
mysql_errno: 0
error:
message_text: NULL
5 rows in set (0.0010 sec)
Listing 16-3Finding the queries involved in the deadlock
注意,对于连接 id 763(第二个事务),包含了 MySQL 错误号,第三行将其设置为 1213——这是一个死锁。当遇到错误时,MySQL Shell 自动执行一个SHOW WARNINGS语句,即第 4 行中的语句。还要注意,嵌套事件是事务 2 的ROLLBACK的NULL,而不是事务 1 的ROLLBACK。这是因为死锁触发了整个事务的回滚(所以事务 2 的ROLLBACK没有做任何事情)。
死锁是由事务 1 首先更新city表的填充,然后更新country表的填充触发的。事务 2 首先更新了country表的人口,然后试图将一个新的城市插入到city表中。这是两个工作流以不同顺序更新记录的典型例子,因此容易出现死锁。
总结调查,它包括两个步骤:
-
分析来自 InnoDB 的死锁信息,以确定死锁中涉及的锁,并获得尽可能多的关于连接的信息。
-
使用其他来源(如性能模式)来查找有关事务中查询的更多信息。通常有必要分析应用以获得查询列表。
现在您已经知道是什么触发了死锁,那么解决这个问题需要什么呢?
解决方案
死锁是最容易解决的锁情况,因为 InnoDB 会自动选择一个事务作为受害者并回滚它。在前面讨论的死锁中,事务 2 被选为受害者,这可以从死锁输出中看出:
*** WE ROLL BACK TRANSACTION (2)
这意味着对于事务 1,没有什么可做的。事务 2 回滚后,事务 1 可以继续并完成其工作。
对于事务 2,InnoDB 已经回滚了整个事务,所以您需要做的就是重试该事务。记住再次执行所有查询,而不是依赖第一次尝试时返回的值;否则,您可能会使用过时的值。
Tip
时刻准备处理死锁和锁等待超时。对于死锁或当事务在锁等待超时后回滚时,请重试整个事务。对于仅回滚查询的锁等待超时,重试查询可能会增加延迟。
如果死锁相对很少发生,您实际上不需要做更多的事情。死锁是生活中的现实,所以不要因为遇到一些死锁而惊慌。如果死锁造成了重大影响,您需要考虑进行一些更改来防止某些死锁。
预防
减少死锁与减少记录锁争用非常相似,只是在整个应用中以相同的顺序获取锁非常重要。建议再次阅读关于减少锁定问题的第 9 章:
-
通过将大型事务分成几个较小的事务,并添加索引以减少锁的数量,来减少每个事务所做的工作。
-
如果事务隔离级别适合于您的应用来减少锁的数量和它们被持有的时间,那么可以考虑使用它。
-
确保事务只在尽可能短的时间内保持开放。
-
以相同的顺序访问记录,如果需要的话,可以通过执行
SELECT ... FOR UPDATE或SELECT ... FOR SHARE查询来抢占锁。
减少死锁的要点是减少锁的数量和持有锁的时间,并以相同的顺序获取锁。
摘要
在这个案例研究中,死锁是通过模拟一个更新一个国家中所有城市人口的工作负载,然后更新该国家的人口而产生的。同时,另一个连接将一个新城市添加到同一个国家,但首先更新该国的人口,然后插入新城市。这是一个经典的例子,说明了为什么使用相同表但顺序相反的两个不同工作流会出现死锁。
主要使用 InnoDB 监控器输出的LATEST DETECTED DEADLOCK部分来调查死锁。由此可以看出涉及到哪些连接、它们执行的最后一条语句、它们持有的锁以及它们正在等待的锁。此外,带有语句历史的性能模式表用于查找事务中涉及的确切语句;但是,通常情况下,您没有这种能力,必须分析应用来确定所涉及的语句。
发生死锁时的好消息是,它会通过回滚其中一个事务来自动解决自身问题,以便另一个事务可以继续。然后,您必须重试受害者事务。如果您有太多的死锁,关键是要减少锁的数量和它们的持续时间,并确保您在不同的任务中以相同的顺序使用锁。
在下一章中,您将研究外键引起锁争用的情况。
十七、案例研究:外键
最难调查的锁争用情况之一发生在涉及外键的时候,因为您可以对不同的表内容查询相同的锁。本案例研究调查了一个由于外键而导致元数据和 InnoDB 记录锁定的例子。由于症状和原因与第章第 14 节讨论元数据锁的案例研究和第章第 15 节讨论 InnoDB 记录锁的案例研究相同,因此在本讨论中省略。
设置
这个案例研究比前几个更复杂,没有一个简单的方法可以自行重现。但是,MySQL Shell 的concurrency_book模块中的Listing 17-1 工作负载将允许您重现争用。工作负载由五个连接组成:
-
更新
sakila.customer表的两个连接,以这种方式,总是有一个事务正在进行,并且在表上有一个元数据和记录锁。在COMMIT之前有一个休眠,以确保持续时间足够长,以避免竞争情况。休眠的持续时间可以在工作负载执行期间进行配置。 -
一个在
sakila.inventory表上执行ALTER TABLE的连接。这个用lock_wait_timeout = 1。 -
一个更新
sakila.film_category表的连接。 -
一个更新
sakila.category表的连接。这个用的是innodb_lock_wait_timeout = 1。
当您执行工作负载时,在输入密码之后,您将被要求输入测试的运行时间,以及更新sakila.customer表的两个连接应该休眠多长时间来提交它们的事务。睡眠被指定为乘以 0.1 秒的因子。
Note
测试不具有确定性,因为即使重现相同的问题,您也应该预期会看到不同的数据。
测试开始后,将显示各种监控输出,以便您可以调查问题。
清单 17-1 显示了工作负载的一个示例执行的部分输出(遇到的锁的确切数量和各种指标的值将因执行而异)。完整的输出可以在本书的 GitHub 库的listing_17-1.txt中找到。本章剩余部分的讨论中也会用到输出的几个部分。
Specify the number of seconds to run for (10-3600) [15]:
Specify the sleep factor (0-30) [15]:
-- Connection Processlist ID Thread ID Event ID
-- --------------------------------------------------
-- 1 462 792 6
-- 2 463 793 6
-- 3 464 794 6
-- 4 465 795 6
-- 5 466 796 6
mysql> SELECT error_number, error_name, sum_error_raised
FROM performance_schema.events_errors_summary_global_by_error
WHERE error_name IN ('ER_LOCK_WAIT_TIMEOUT', 'ER_LOCK_DEADLOCK');
+--------------+----------------------+------------------+
| error_number | error_name | sum_error_raised |
+--------------+----------------------+------------------+
| 1205 | ER_LOCK_WAIT_TIMEOUT | 310 |
| 1213 | ER_LOCK_DEADLOCK | 12 |
+--------------+----------------------+------------------+
...
mysql> UPDATE sakila.category SET name = IF(name = 'Travel', 'Exploring', 'Travel') WHERE category_id = 16;
ERROR: 1205: Lock wait timeout exceeded; try restarting transaction
mysql> ALTER TABLE sakila.inventory FORCE;
ERROR: 1205: Lock wait timeout exceeded; try restarting transaction -- Metrics reported by rate collected during the test:
time,innodb_row_lock_time,innodb_row_lock_waits,lock_deadlocks,lock_timeouts
2020-08-02 14:17:12.168000,0.0,0.0,0.0,0.0
2020-08-02 14:17:13.180000,0.0,0.0,0.0,0.0
2020-08-02 14:17:14.168000,0.0,1.0121457489878543,0.0,0.0
2020-08-02 14:17:15.177000,0.0,0.0,0.0,0.0
2020-08-02 14:17:16.168000,2019.1725529767912,1.0090817356205852,0.0,1.0090817356205852
2020-08-02 14:17:17.169000,0.0,0.0,0.0,0.0
2020-08-02 14:17:18.180000,1541.0484668644908,0.0,0.0,0.9891196834817014
2020-08-02 14:17:19.180000,0.0,0.0,0.0,0.0
2020-08-02 14:17:20.168000,0.0,0.0,0.0,0.0
2020-08-02 14:17:21.180000,0.0,0.0,0.0,0.0
2020-08-02 14:17:22.168000,82.99595141700405,2.0242914979757085,0.0,0.0
2020-08-02 14:17:23.179000,0.0,0.0,0.0,0.0
2020-08-02 14:17:24.180000,1997.0029970029973,0.9990009990009991,0.0,0.9990009990009991
2020-08-02 14:17:25.179000,0.0,0.0,0.0,0.0
2020-08-02 14:17:26.182000,2115.6530408773683,0.9970089730807579,0.0,0.9970089730807579
2020-08-02 14:17:27.180000,0.0,0.0,0.0,0.0
2020-08-02 14:17:28.168000,0.0,0.0,0.0,0.0
2020-08-02 14:17:29.180000,0.0,0.0,0.0,0.0
2020-08-02 14:17:30.168000,66.80161943319838,2.0242914979757085,0.0,0.0
mysql> SELECT error_number, error_name, sum_error_raised
FROM performance_schema.events_errors_summary_global_by_error
WHERE error_name IN ('ER_LOCK_WAIT_TIMEOUT', 'ER_LOCK_DEADLOCK');
+--------------+----------------------+------------------+
| error_number | error_name | sum_error_raised |
+--------------+----------------------+------------------+
| 1205 | ER_LOCK_WAIT_TIMEOUT | 317 |
| 1213 | ER_LOCK_DEADLOCK | 12 |
+--------------+----------------------+------------------+
...
2020-08-02 14:17:30.664018 0 [INFO] Stopping the threads.
2020-08-02 14:17:33.818122 0 [INFO] Completing the workload Listing 17-1
2020-08-02 14:17:33.820075 0 [INFO] Disconnecting for the workload Listing 17-1
2020-08-02 14:17:33.820075 0 [INFO] Completed the workload Listing 17-1
Listing 17-1Locks and foreign keys
首先,提示运行时和睡眠因素的问题。对于这个讨论,默认值将起作用,但是鼓励您尝试其他设置来进行您自己的测试。特别的,将睡眠因子降低到 8 或更低会使ALTER TABLE开始成功,你会看到ER_LOCK_DEADLOCK计数器递增;这是一个元数据死锁。
Note
由于 MySQL Shell 中的并发工作负载并不完全是线程安全的,因此有时有必要重试测试。
其次,打印一些初始监控信息。在测试结束时执行相同的监控,因此您可以获得关于发生的错误数量和其他指标的信息。测试结束时的监控信息还包括 CSV 格式的信息,您可以将其复制到电子表格中,例如,为其创建图表。
否则,输出包含关于元数据锁和锁等待的信息,以及经历锁等待超时的语句。
讨论
调查通常会经历几个步骤。首先,将涵盖应用和监控记录的错误。其次,讨论锁指标。第三,介绍了元数据锁,最后讨论了 InnoDB 锁争用。
错误和高级监控
您可能注意到的第一件事是应用遇到了错误;在这种情况下,它们是锁等待超时。在现实世界中,您可能不会像在本案例研究中那样直接获得错误。如果您不处理这些错误,您可能会看到应用出错,甚至崩溃。务必处理错误,最好记录错误,这样您就可以跟踪应用遇到的问题,并且可以使用 Splunk 1 等日志分析器来分析错误的频率。本案例研究中的错误示例包括
mysql> UPDATE sakila.category SET name = IF(name = 'Travel', 'Exploring', 'Travel') WHERE category_id = 16;
ERROR: 1205: Lock wait timeout exceeded; try restarting transaction
mysql> ALTER TABLE sakila.inventory FORCE;
ERROR: 1205: Lock wait timeout exceeded; try restarting transaction
您还可以查看您的监控,其中应该包括与图 17-1 所示类似的关于 InnoDB 锁等待的信息,即 InnoDB 锁等待的次数、InnoDB 锁等待超时的次数以及在测试期间测量的 InnoDB 锁时间(毫秒)。
图 17-1
InnoDB 锁等待指标
当前等待是直接测量,而锁超时和锁时间是与前一次测量的差异。当前等待和锁定超时使用左侧的 y 轴,并由条形表示,而锁定时间使用右侧的 y 轴显示在折线图中。x 轴是测试开始的时间。
从图中可以看到锁定问题是间歇性的,您可以使用它来确定问题发生的时间。如果您有一个监控解决方案,允许您查看在给定的时间间隔内哪些查询正在运行,那么您可以使用它来调查导致锁等待的工作负载。支持这一点的监控解决方案的例子有 MySQL Enterprise Monitor(也称为 MEM) 2 、Solarwinds 数据库性能监控器(DPM,以前的 VividCortex) 3 和 Percona 监控和管理(PMM)。 4
锁定指标
通过监控锁指标,可以很容易地发现锁争用增加的时段,并且值得进一步讨论这些指标。对于 InnoDB 来说,监控锁等待很简单,就像刚才显示的那样,但是不幸的是,对于元数据锁来说,没有可以轻松给出相同信息的度量标准。您可以使用性能模式中的错误统计信息来跟踪锁等待超时和死锁的数量:
mysql> SELECT error_number, error_name, sum_error_raised
FROM performance_schema.events_errors_summary_global_by_error
WHERE error_name IN ('ER_LOCK_WAIT_TIMEOUT', 'ER_LOCK_DEADLOCK');
+--------------+----------------------+------------------+
| error_number | error_name | sum_error_raised |
+--------------+----------------------+------------------+
| 1205 | ER_LOCK_WAIT_TIMEOUT | 310 |
| 1213 | ER_LOCK_DEADLOCK | 12 |
+--------------+----------------------+------------------+
...
mysql> SELECT error_number, error_name, sum_error_raised
FROM performance_schema.events_errors_summary_global_by_error
WHERE error_name IN ('ER_LOCK_WAIT_TIMEOUT', 'ER_LOCK_DEADLOCK');
+--------------+----------------------+------------------+
| error_number | error_name | sum_error_raised |
+--------------+----------------------+------------------+
| 1205 | ER_LOCK_WAIT_TIMEOUT | 317 |
| 1213 | ER_LOCK_DEADLOCK | 12 |
+--------------+----------------------+------------------+
这表明在这个测试中,有七次锁等待超时,没有死锁。这个信息的问题是,它没有告诉您是元数据锁、InnoDB 锁还是第三种锁类型经历了锁等待超时或死锁。也就是说,由于 InnoDB 有自己的锁等待超时和死锁统计数据,您可以通过减去这两个统计数据来获得非 InnoDB 锁的数量。清单 17-2 中显示了测试的 InnoDB 锁统计数据。
mysql> SELECT Variable_name, Variable_value
FROM sys.metrics
WHERE Variable_name IN (
'innodb_row_lock_current_waits',
'lock_row_lock_current_waits',
'innodb_row_lock_time',
'innodb_row_lock_waits',
'lock_deadlocks',
'lock_timeouts'
);
+-------------------------------+----------------+
| Variable_name | Variable_value |
+-------------------------------+----------------+
| innodb_row_lock_current_waits | 0 |
| innodb_row_lock_time | 409555 |
| innodb_row_lock_waits | 384 |
| lock_deadlocks | 0 |
| lock_row_lock_current_waits | 0 |
| lock_timeouts | 188 |
+-------------------------------+----------------+
...
mysql> SELECT Variable_name, Variable_value
FROM sys.metrics
WHERE Variable_name IN (
'innodb_row_lock_current_waits',
'lock_row_lock_current_waits',
'innodb_row_lock_time',
'innodb_row_lock_waits',
'lock_deadlocks',
'lock_timeouts'
)
+-------------------------------+----------------+
| Variable_name | Variable_value |
+-------------------------------+----------------+
| innodb_row_lock_current_waits | 1 |
| innodb_row_lock_time | 417383 |
| innodb_row_lock_waits | 392 |
| lock_deadlocks | 0 |
| lock_row_lock_current_waits | 1 |
| lock_timeouts | 192 |
+-------------------------------+----------------+
Listing 17-2The InnoDB lock statistics for the test
在这里,您可以看到在总共七个ER_LOCK_WAIT_TIMEOUT错误中,总共有四个 InnoDB 锁等待超时(lock_timeouts状态计数器),因此您可以得出结论,有三个非 InnoDB 锁等待超时。在这个案例研究中,这些都是元数据锁定等待超时。
元数据锁争用
实际上,如果您能在锁争用正在进行时捕捉到它,这是最好的,如前面的案例研究所示。在这个例子的输出中,有来自performance_schema.metadata_locks表以及schema_table_lock_waits和innodb_lock_waits sys模式视图的输出。metadata_locks表突出显示了元数据锁定的范围,这可以从清单 17-3 中看出。
mysql> SELECT object_name, lock_type, lock_status,
owner_thread_id, owner_event_id
FROM performance_schema.metadata_locks
WHERE object_type = 'TABLE'
AND object_schema = 'sakila'
ORDER BY owner_thread_id, object_name, lock_type\G
*************************** 1\. row ***************************
object_name: category
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 792
owner_event_id: 9
*************************** 2\. row ***************************
object_name: film
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 792
owner_event_id: 9
*************************** 3\. row ***************************
object_name: film_category
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 792
owner_event_id: 9
*************************** 4\. row ***************************
object_name: category
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 793
owner_event_id: 9
*************************** 5\. row ***************************
object_name: film
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 793
owner_event_id: 9
*************************** 6\. row ***************************
object_name: film_category
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 793
owner_event_id: 9
*************************** 7\. row ***************************
object_name: address
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 8\. row ***************************
object_name: customer
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 9\. row ***************************
object_name: inventory
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 10\. row ***************************
object_name: payment
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 11\. row ***************************
object_name: rental
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 12\. row ***************************
object_name: staff
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 13\. row ***************************
object_name: store
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 794
owner_event_id: 10
*************************** 14\. row ***************************
object_name: address
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 795
owner_event_id: 10
*************************** 15\. row ***************************
object_name: customer
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 795
owner_event_id: 10
*************************** 16\. row ***************************
object_name: inventory
lock_type: SHARED_READ
lock_status: PENDING
owner_thread_id: 795
owner_event_id: 10
*************************** 17\. row ***************************
object_name: payment
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 795
owner_event_id: 10
*************************** 18\. row ***************************
object_name: rental
lock_type: SHARED_WRITE
lock_status: GRANTED
owner_thread_id: 795
owner_event_id: 10
*************************** 19\. row ***************************
object_name: staff
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 795
owner_event_id: 10
*************************** 20\. row ***************************
object_name: store
lock_type: SHARED_READ
lock_status: GRANTED
owner_thread_id: 795
owner_event_id: 10
*************************** 21\. row ***************************
object_name: #sql-35e8_1d2
lock_type: EXCLUSIVE
lock_status: GRANTED
owner_thread_id: 796
owner_event_id: 9
*************************** 22\. row ***************************
object_name: film
lock_type: SHARED_UPGRADABLE
lock_status: GRANTED
owner_thread_id: 796
owner_event_id: 9
*************************** 23\. row ***************************
object_name: inventory
lock_type: EXCLUSIVE
lock_status: PENDING
owner_thread_id: 796
owner_event_id: 9
*************************** 24\. row ***************************
object_name: inventory
lock_type: SHARED_UPGRADABLE
lock_status: GRANTED
owner_thread_id: 796
owner_event_id: 9
*************************** 25\. row ***************************
object_name: rental
lock_type: SHARED_UPGRADABLE
lock_status: GRANTED
owner_thread_id: 796
owner_event_id: 9
*************************** 26\. row ***************************
object_name: store
lock_type: SHARED_UPGRADABLE
lock_status: GRANTED
owner_thread_id: 796
owner_event_id: 9
Listing 17-3The metadata locks found during the test
两个挂起的锁(第 16 和 23 行)用于customer表上的ALTER TABLE和其中一个UPDATE语句。
在收集该输出的时间点,仅 5 个线程就有 26 个被授予或挂起的元数据锁。所有语句只查询一个表(从技术上讲,ALTER TABLE还有第二个表——在本例中是名为#sql-35e8_1d2的表,但这是用于重建inventory表的临时表名)。按表名对锁进行分组,您可以看到包括临时表在内的 11 个表都有元数据锁(这些数字可能与前面的输出不一致,因为它们不是在完全相同的时间生成的):
mysql> SELECT object_name, COUNT(*)
FROM performance_schema.metadata_locks
WHERE object_type = 'TABLE'
AND object_schema = 'sakila'
GROUP BY object_name
ORDER BY object_name;
+---------------+----------+
| object_name | COUNT(*) |
+---------------+----------+
| #sql-35e8_1d2 | 1 |
| address | 2 |
| category | 2 |
| customer | 2 |
| film | 3 |
| film_category | 2 |
| inventory | 4 |
| payment | 2 |
| rental | 3 |
| staff | 2 |
| store | 3 |
+---------------+----------+
所有这些表受到影响的原因是,sakila模式大量使用外键。图 17-2 显示了这些表及其外键关系。在该图中,只包括属于表主键或外键的列。
图 17-2
测试中表之间的关系
为了找到导致ALTER TABLE锁定等待超时的语句,最简单的方法是使用第 14 章中讨论的sys.schema_table_lock_waits视图。这些步骤留给读者作为练习。冲突的语句是customer表上的更新和inventory表上的ALTER TABLE。
InnoDB 锁争用
当您考虑上一节中表之间的外键关系时,很容易得出这样的结论,即category表上的UPDATE语句的锁等待超时也是由于从inventory表上的ALTER TABLE级联的元数据锁造成的。然而,在做出这样的结论之前,你必须小心谨慎,研究事实——而在这种情况下,结论是错误的。
如果查看来自metadata_locks表的信息,可以看到没有一个挂起的锁是针对category表的:
*************************** 16\. row ***************************
object_name: inventory
lock_type: SHARED_READ
lock_status: PENDING
owner_thread_id: 795
owner_event_id: 10
...
*************************** 23\. row ***************************
object_name: inventory
lock_type: EXCLUSIVE
lock_status: PENDING
owner_thread_id: 796
owner_event_id: 9
这是这里的关键信息。虽然模式知识很重要,但是您应该从查看锁等待信息开始,然后使用模式知识来理解为什么会发生锁,而不是试图根据模式知识猜测可能存在什么锁。
前面讨论的监控确实显示存在 InnoDB 锁等待超时,清单 17-4 中的sys.innodb_lock_waits输出显示了哪些是冲突的锁和语句。
mysql> SELECT * FROM sys.innodb_lock_waits\G
*************************** 1\. row ***************************
wait_started: 2020-08-02 14:17:13
wait_age: 00:00:02
wait_age_secs: 2
locked_table: `sakila`.`category`
locked_table_schema: sakila
locked_table_name: category
locked_table_partition: None
locked_table_subpartition: None
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 535860
waiting_trx_started: 2020-08-02 14:17:13
waiting_trx_age: 00:00:02
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 463
waiting_query: UPDATE sakila.category SET name = IF(name = 'Travel', 'Exploring', 'Travel') WHERE category_id = 16
waiting_lock_id: 2711671600928:1795:4:282:2711634698920
waiting_lock_mode: X,REC_NOT_GAP
blocking_trx_id: 535859
blocking_pid: 462
blocking_query: None
blocking_lock_id: 2711671600096:1795:4:282:2711634694976
blocking_lock_mode: S,REC_NOT_GAP
blocking_trx_started: 2020-08-02 14:17:13
blocking_trx_age: 00:00:02
blocking_trx_rows_locked: 5
blocking_trx_rows_modified: 2
sql_kill_blocking_query: KILL QUERY 462
sql_kill_blocking_connection: KILL 462
1 row in set (0.0017 sec)
Listing 17-4The InnoDB lock waits during the test
锁争用发生在category表的主键上,进程列表 id 462 是阻塞连接。该连接在输出时是空闲的,因此您需要使用性能模式语句历史表或监控解决方案中的查询分析,或者研究应用或它们的组合来确定事务执行了哪些查询。在这种情况下,它是对film_category表的更新(为了可读性而格式化):
UPDATE sakila.film_category
SET category_id = IF(category_id = 7, 16, 7)
WHERE film_id = 64;
这导致对category表的锁定的原因是在film_category和category表中的category_id列之间有一个外键,所以当进程列表 id 为 463 的连接试图更新与连接 462 更新的 id 相同的category表中的行时,它将阻塞,直到 462 被提交或回滚。
解决方案和预防措施
第 14 和 15 章中讨论的解决方案和预防措施也适用于涉及外键的情况。这意味着首先避免这些问题的最有效方法是避免长时间运行的事务,作为解除元数据锁等待的快速方法,您可以终止请求排他锁的 DDL 语句。
Note
外键是元数据锁比 InnoDB 记录锁更大的问题,因为后者只影响外键中使用的列。
当存在外键时,将lock_wait_timeout保持在一个较低的值会特别有用,这样可以避免在等待所有请求被批准时,跨许多表请求或长时间持有大量元数据锁定请求。这可能与减少max_write_lock_count的值相结合,以避免延迟通过繁忙表上的外键请求的共享元数据锁的请求。(减少max_write_lock_count不会改变这个案例研究。)
如果由于外键而出现锁争用的严重问题,一种可能是将保持数据一致性的责任转移到应用中。但是,您应该意识到,这确实会在 MySQL 级别上移除保险,以保持数据的一致性(ACID 中的 C ),因此不建议这样做。也就是说,在某些情况下,这可能是避免高并发系统中过度锁定的唯一方法。
Caution
虽然在应用中处理外键关系有助于减少数据库中的锁定,但是要小心,因为这也会削弱一致性保证。
此外,还存在一些通用的解决方案,它们并不专门针对外键:
-
如果锁被持有的时间太长,例如,由于一个被放弃的事务,可以考虑终止阻塞的事务,但是要记住考虑必须回滚的更改的数量。
-
请记住,处理查询因锁等待超时而失败的事务,这样事务就不会保留在失败的语句之前获取的锁。
-
考虑一下你能做些什么来减少事务的持续时间和规模。
-
使用索引来减少被访问的记录数量。
-
考虑一下
READ COMMITTED事务隔离级别,如果它适合您的应用的话。
摘要
本章通过一个案例研究了由外键引起的同步元数据锁和 InnoDB 锁争用。主要讨论点是锁如何传播到查询所使用的表之外的其他表。对于元数据锁来说尤其如此,而对于 InnoDB 记录锁来说影响较小,因为只有在涉及到用于外键的列时才会使用额外的锁。
调查锁问题的原理与不涉及外键时的原理相同;然而,由于涉及的锁的数量,这更加困难;对于示例中的元数据锁,performance_schema.metadata_locks返回了 26 个锁请求。因此,使用sys模式视图来帮助分析特别有用。
除了减少锁问题的常用方法之外,对于元数据锁,您可以考虑将较低的lock_wait_timeout与相对较低的max_write_lock_count值相结合。另一个对元数据和 InnoDB 锁都有帮助的选项是将保证外键一致性的责任留给应用;但是,如果你这样做的话要非常小心,因为它不会像 MySQL 处理它时那样提供强有力的保证。
还有一个案例研究,它涵盖了 InnoDB 中存在信号量等待的情况,这将在下一章中讨论。
Footnotes [1](#Fn1_source)https://www.mysql.com/products/enterprise/monitor.html
https://www.solarwinds.com/database-performance-monitor
https://www.percona.com/software/database-tools/percona-monitoring-and-management
十八、案例研究:信号量
互斥和信号量争用是您可能遇到的最难以捉摸的争用类型之一,因为除了极端情况,您不会直接注意到任何问题。相反,这种争用往往会导致整体延迟增加和吞吐量降低,很难确定具体原因。然后,出乎意料的是,您可能已经超过了一个负载阈值,这种争用导致您的服务器突然停止工作。
本章通过一个案例来研究自适应散列索引 rw-semaphore 上的争用。但是,请注意,信号量争用根据发生争用的互斥体或信号量的不同而不同,解决它所需的调查也不同。在高严重性的情况下,您可能还会发现多个信号量等待同时发生争用。
症状
注意到 InnoDB 互斥体或信号量存在争用的两种最常见的方法是通过 InnoDB monitor 和innodb_rwlock_% InnoDB metrics。
例如,在 InnoDB monitor 输出中,您会在靠近输出顶部的SEMAPHORES部分看到正在进行的等待
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 77606
--Thread 19304 has waited at btr0sea.ic line 122 for 0 seconds the semaphore:
S-lock on RW-latch at 00000215E6DC12F8 created in file btr0sea.cc line 202
a writer (thread id 11100) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\btr\btr0sea.cc line 1197
--Thread 26128 has waited at btr0sea.ic line 92 for 0 seconds the semaphore:
X-lock on RW-latch at 00000215E6DC12F8 created in file btr0sea.cc line 202
a writer (thread id 11100) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\btr\btr0sea.cc line 1197
OS WAIT ARRAY INFO: signal count 93040
RW-shared spins 18200, rounds 38449, OS waits 20044
RW-excl spins 22345, rounds 1121445, OS waits 38469
RW-sx spins 3684, rounds 100410, OS waits 2886
Spin rounds per wait: 2.11 RW-shared, 50.19 RW-excl, 27.26 RW-sx
等待的时间越长,问题就越严重。
您可能还会在监控中注意到,rw-lock 等待的次数很高,在高负载时可能会达到峰值。在一个真实的例子中,自适应散列索引存在严重的争用,在很长一段时间内,每秒钟有数万次操作系统等待。
原因
问题是对共享资源的请求,比如对自适应散列索引的访问,到达的速度比它们能够被处理的速度要快。这些资源在源代码中使用互斥锁和读写锁进行保护。争用表明要么您已经达到了您的工作负载所使用的 MySQL 版本的并发限制,要么您需要将资源分成更多的部分或类似的部分。
设置
随意再现信号量争用可能很难做到。系统中可用的 CPU 越多,就越有可能产生遇到信号量等待的工作负载。
本章讨论的输出是在带有八个 CPU 的笔记本电脑上使用Listing 8-1 工作负载生成的,缓冲池的默认大小设置为 128 MiB。如果您试图重现这种情况,那么您可能需要试验连接的数量。该脚本提示您将这些默认设置为 1 个读写线程,并将每个剩余 CPU 的一个连接用于只读连接。
Note
MySQL Shell 的会话对象并不完全是线程安全的,即使每个线程都有自己的会话。因此,有必要尝试几次测试。该问题在具有多个读写连接的 Microsoft Windows 上尤其明显。
您还可以尝试更改缓冲池的大小。还有一个选项是在提交事务时减少刷新,如果您的磁盘刷新性能较差,这尤其有用:
SET GLOBAL innodb_flush_log_at_trx_commit = 0,
GLOBAL sync_binlog = 0;
Caution
减少刷新在测试系统上是没问题的,但是您不应该在生产系统上这样做,因为您可能会在崩溃的情况下丢失提交的事务。
运行更长时间也可以增加至少看到一次争用的机会。
测试还允许您在测试之前请求重新启动 MySQL,并且您可以选择是否删除测试创建的索引。重新启动 MySQL 可以让您看到从一个冷的 InnoDB 缓冲池开始的区别(尽管工作负载确实会自己预热缓冲池)。
Note
从测试中重新启动 MySQL 只有在您已经在管理进程下启动 MySQL 的情况下才有效。例如,当您在 Microsoft Windows 上使用mysqld_safe或在 Linux 上通过systemd将 MySQL 作为一项服务启动时,就会发生这种情况。
如果您想要多次运行测试,告诉测试不要删除它的索引可能是一个优势,因为这允许测试在下一次执行时跳过创建。
清单 18-1 中显示了一个执行测试用例的例子。执行的完整输出包含在文件listing_18-1.txt中,该文件可从本书的 GitHub 存储库中获得。
Specify the number of read-write connections (0-31) [1]:
Specify the number of read-only connections (1-31) [7]:
Specify the number of seconds to run for (1-3600) [10]:
Restart MySQL before executing the test? (Y|Yes|N|No) [No]:
Delete the test specific indexes after executing the test? (Y|Yes|N|No) [Yes]:
2020-07-25 15:56:33.928772 0 [INFO] Adding 1 index to the dept_emp table
2020-07-25 15:56:43.238872 0 [INFO] Adding 1 index to the employees table
2020-07-25 15:56:54.202735 0 [INFO] Adding 1 index to the salaries table
2020-07-25 15:57:47.050114 0 [INFO] Warming up the InnoDB buffer pool.
2020-07-25 15:58:04.543354 0 [INFO] Waiting 2 seconds to let the monitoring collect some information before starting the test.
2020-07-25 15:58:06.544765 0 [INFO] Starting the work connections.
2020-07-25 15:58:07.556126 0 [INFO] Completed 10%
…
-- Total mutex and rw-semaphore waits during test:
+----------------+-------+
| File:Line | Waits |
+----------------+-------+
| btr0sea.cc:202 | 13368 |
+----------------+-------+
-- Total execution time: 25.685603 seconds
2020-07-25 15:58:34.374196 0 [INFO] Dropping indexes on the dept_emp table.
2020-07-25 15:58:35.651209 0 [INFO] Dropping indexes on the employees table.
2020-07-25 15:58:36.344171 0 [INFO] Dropping indexes on the salaries table.
Listing 18-1Semaphore waits
注意,在这个例子的开始,有五个关于如何运行测试的信息提示。
当测试重现该问题时,您将从 InnoDB monitor 输出中看到一个或多个SEMAPHORES部分的输出,最后会生成一些诊断数据。这些数据包括
-
测试期间每秒收集的 RW-lock 指标。这是以 CSV 格式打印的,因此您可以将其复制到电子表格中并绘制出来。
-
测试期间每秒收集的自适应哈希索引指标。这也是以 CSV 格式打印的。
-
InnoDB 缓冲池中的总页数以及年轻或不年轻的比率。
-
测试结束时的
INSERT BUFFER AND ADAPTIVE HASH INDEX部分。 -
测试期间互斥和 rw 信号量等待的总数。
只读工作负载由employees数据库中三个表之间的连接组成,其中包括大量的二级索引查找:
SELECT dept_name, MIN(salary) min_salary,
AVG(salary) AS avg_salary, MAX(salary) AS max_salary
FROM employees.departments
INNER JOIN employees.dept_emp USING (dept_no)
INNER JOIN employees.salaries USING (emp_no)
WHERE dept_emp.to_date = '9999-01-01'
AND salaries.to_date = '9999-01-01'
GROUP BY dept_no
ORDER BY dept_name;
读写工作负载从employees.employees表中随机选择一个姓氏,并给所有姓该姓氏的员工加薪。对于占位符,步骤如下
SELECT last_name
FROM employees.employees
WHERE emp_no = ?;
SELECT emp_no, salary, from_date + INTERVAL 1 DAY
FROM employees.employees
INNER JOIN employees.salaries USING (emp_no)
WHERE employees.last_name = ?
AND to_date = '9999-01-01';
# For each employee found in the previous query,
# execute the insert and update:
INSERT INTO employees.salaries
VALUES (?, ?, ?, '9999-01-01');
UPDATE employees.salaries
SET to_date = ?
WHERE emp_no = ? AND to_date = '9999-01-01';
这意味着employees数据库中的数据被修改。您不需要在每次测试之间重新加载数据,但是如果您希望返回原始数据,您可能希望在完成测试后重置它。
表中添加了三个索引,以确保存在导致争用的必要辅助索引(请记住,自适应散列索引仅用于辅助索引):
ALTER TABLE employees.dept_emp
ADD INDEX idx_concurrency_book_0 (dept_no, to_date);
ALTER TABLE employees.employees
ADD INDEX idx_concurrency_book_1 (last_name, first_name);
ALTER TABLE employees.salaries
ADD INDEX idx_concurrency_book_2 (emp_no, to_date, salary);
除非您请求保留索引,否则在测试结束时会再次删除索引。
最后,为了避免在测试期间过早驱逐读入缓冲池的页面,在测试期间,旧块时间被设置为 0:
SET GLOBAL innodb_old_blocks_time = 0;
这有助于将缓冲池置于比其他情况下更高的压力之下,从而更有可能再现争用。测试结束时,变量被设置回 1000(默认值)。
Note
测试将花费比您指定的运行时间更长的时间,因为运行时间只在每个查询循环开始时检查。因此,循环中所有挂起的查询都将完成。
现在已经确定了导致问题的工作负载,是时候开始调查了。
调查
当您遇到信号量争用时,第一个访问的端口通常是您的监控系统,在那里您可以获得争用的概况。虽然您可以自己查询指标,但是信号量等待往往是波动的,您很可能会在没有争用的时段看到问题,并且只在最繁忙的时段或执行特定工作负载时看到问题。通过查看图表中的指标,可以更容易地确定何时发生争用。
本节讨论如何监控innodb_rwlock_%指标、InnoDB 监控器的SEMAPHORES部分、InnoDB 互斥监控器,以及如何确定工作负载。
InnoDB 读写锁指标
一种选择是从查看来自information_schema.INNODB_METRICS或sys.metrics的innodb_rwlock_%指标开始调查。有三组指标:共享、共享独占和独占读写锁。每个组有三个指标:旋转等待数、旋转轮数和操作系统等待数。测试结束时的 CSV 输出包括共享组和独占组的指标。(本研究对共享独占读写锁不感兴趣。)图 18-1 显示了一个共享读写锁的度量标准示例,该示例在 x 轴上绘制了进入测试的时间。
图 18-1
共享读写锁的等待和旋转次数
在这里,旋转等待的次数在测试过程中几乎是恒定的,但是旋转循环的次数(图中的顶线)在测试进行到大约 7 秒时显著增加。这也会导致操作系统等待的次数增加。操作系统等待跳转意味着旋转等待的旋转圈数超过innodb_sync_spin_loops(默认为 30)。
专用 rw 锁的图片与此类似,只是旋转圈数要高得多,如图 18-2 所示。
图 18-2
独占读写锁的等待和旋转次数
虽然很难看出,因为旋转轮的数量使旋转和操作系统等待相形见绌,但它们确实遵循与共享读写锁相同的模式,等待的绝对数量大约是共享锁的两倍。引起关注的等待次数取决于您的工作负载,您的并发查询越多,通常等待次数就越多。您应该特别注意操作系统等待,因为当等待时间太长以至于线程被挂起时,操作系统等待会增加。
InnoDB 监控器和互斥监控器
当您确定发生争用的时间后,您需要确定争用是针对哪个读写锁(可能有多个读写锁)。有两个主要工具可以确定发生争用的位置,其中第一个工具是 InnoDB monitor。除非您已经启用了它,所以它会自动输出到错误日志,或者争用非常严重,以至于信号量等待时间超过了 240 秒,否则您需要在遇到争用时捕获您的系统。清单 18-2 显示了测试中 InnoDB 监控器输出的SEMAPHORES部分的示例。
mysql> SHOW ENGINE INNODB STATUS\G
...
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 36040
--Thread 35592 has waited at btr0sea.ic line 92 for 0 seconds the semaphore:
X-lock on RW-latch at 000001BD277CCFF8 created in file btr0sea.cc line 202
a writer (thread id 25492) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\include\btr0sea.ic line 92
--Thread 27836 has waited at btr0sea.ic line 92 for 0 seconds the semaphore:
X-lock on RW-latch at 000001BD277CCFF8 created in file btr0sea.cc line 202
a writer (thread id 25492) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\include\btr0sea.ic line 92
--Thread 25132 has waited at btr0sea.ic line 92 for 0 seconds the semaphore:
X-lock on RW-latch at 000001BD277CCFF8 created in file btr0sea.cc line 202
a writer (thread id 25492) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\include\btr0sea.ic line 92
--Thread 22512 has waited at btr0sea.ic line 92 for 0 seconds the semaphore:
X-lock on RW-latch at 000001BD277CCFF8 created in file btr0sea.cc line 202
a writer (thread id 25492) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\include\btr0sea.ic line 92
--Thread 22184 has waited at btr0sea.ic line 122 for 0 seconds the semaphore:
S-lock on RW-latch at 000001BD277CCFF8 created in file btr0sea.cc line 202
a writer (thread id 25492) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\include\btr0sea.ic line 92
--Thread 32236 has waited at btr0sea.ic line 92 for 0 seconds the semaphore:
X-lock on RW-latch at 000001BD277CCFF8 created in file btr0sea.cc line 202
a writer (thread id 25492) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.ic line 122
Last time write locked in file G:\ade\build\sb_0-39697839-1592332179.68\mysql-8.0.21\storage\innobase\include\btr0sea.ic line 92
OS WAIT ARRAY INFO: signal count 68351
RW-shared spins 9768, rounds 21093, OS waits 11109
RW-excl spins 13012, rounds 669111, OS waits 24669
RW-sx spins 16, rounds 454, OS waits 15
Spin rounds per wait: 2.16 RW-shared, 51.42 RW-excl, 28.38 RW-sx
...
Listing 18-2The SEMAPHORES section of the InnoDB monitor
在这个例子中,所有的等待都是在btr0sea.cc的第 202 行中创建的信号量(行号可能会根据平台和 MySQL 版本的不同而不同,例如,在 Linux 上,8.0.21 的行号是 201)。如果您查看文件storage/innobase/btr/btr0sea.cc中 MySQL 8.0.21 的源代码,那么第 202 行的代码是
186 /** Creates and initializes the adaptive search system at a database start.
187 @param[in] hash_size hash table size. */
188 void btr_search_sys_create(ulint hash_size) {
189 /* Search System is divided into n parts.
190 Each part controls access to distinct set of hash buckets from
191 hash table through its own latch. */
192
193 /* Step-1: Allocate latches (1 per part). */
194 btr_search_latches = reinterpret_cast<rw_lock_t **>(
195 ut_malloc(sizeof(rw_lock_t *) * btr_ahi_parts, mem_key_ahi));
196
197 for (ulint i = 0; i < btr_ahi_parts; ++i) {
198 btr_search_latches[i] = reinterpret_cast<rw_lock_t *>(
199 ut_malloc(sizeof(rw_lock_t), mem_key_ahi));
200
201 rw_lock_create(btr_search_latch_key, btr_search_latches[i],
202 SYNC_SEARCH_SYS);
203 }
...
这是自适应散列索引的代码,因此这证明了自适应散列索引就是争用的地方。(它还显示了第 201 行和第 202 行是针对同一条语句的,因此 Microsoft Windows 和 Linux 之间的行号差异在于选择语句的第一行还是最后一行作为 rw 锁的创建。)
您还可以使用互斥监控器来统计哪些锁是最常经历等待的锁。测试结束时互斥监控器的输出示例如下
mysql> SHOW ENGINE INNODB MUTEX;
+--------+----------------------------+-------------+
| Type | Name | Status |
+--------+----------------------------+-------------+
| InnoDB | rwlock: fil0fil.cc:3206 | waits=11 |
| InnoDB | rwlock: dict0dict.cc:1035 | waits=12 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=7730 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=934 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=5445 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=889 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=9076 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=13608 |
| InnoDB | rwlock: btr0sea.cc:202 | waits=1050 |
| InnoDB | rwlock: hash0hash.cc:171 | waits=4 |
| InnoDB | sum rwlock: buf0buf.cc:778 | waits=86 |
+--------+----------------------------+-------------+
11 rows in set (0.0008 sec)
如果您定期创建 mutex monitor 报告,您可以对等待进行汇总,并按文件和行号进行分组,然后监控等待发生的时间和地点的差异。(本书作者不知道有任何现成的监控解决方案可以做到这一点。)对于这个例子,测试本身计算每个文件的等待次数和行号,这将主要显示对第 202 行btr0sea.cc的等待(记住行号取决于确切的版本和编译器/平台):
-- Total mutex and rw-semaphore waits during test:
+----------------+-------+
| File:Line | Waits |
+----------------+-------+
| btr0sea.cc:202 | 13368 |
+----------------+-------+
您将看到的最有可能的其他文件和行是hash0hash:171(对于 Windows 上的 8.0.21 或 Linux 上的 8.0.21 的第 170 行),它与 InnoDB 的散列表实现相关。这表明 InnoDB monitor 输出中的信号量等待都是针对第 202 行btr0sea.cc的,这不是巧合。
确定工作量
调查的最后一步是确定导致争用的工作负载。这也是最困难的任务。最好是您有一个监控解决方案,它收集关于执行的查询的信息,并为它们聚集统计数据。通过这样的监控,您可以直接看到执行了哪些查询,这可以帮助您确定是什么导致了争用。如果您没有在争用期间执行的查询的访问监控数据,您可以尝试使用sys.session或带有语句信息的性能模式表(threads、events_statements_current、events_statements_history和events_statements_history_long)来监控查询。还有一个选项是使用sys模式中的statement_performance_analyzer()过程,它获取events_statements_summary_by_digest表的两个快照并计算差异,然后返回一个或多个报告,显示关于在两个快照之间执行的查询的信息。
Tip
sys模式中的statement_performance_analyzer()过程可以用来生成一个“穷人的查询分析器”,在两个快照之间执行查询。文档和示例见 https://dev.mysql.com/doc/refman/en/sys-statement-performance-analyzer.html 。
这听起来很容易,但实际操作起来,并不那么简单。即使有良好的监控,也几乎不可能确定哪些查询是问题所在。在真实的生产系统中,峰值可能超过每秒 100000 个查询,每分钟超过 10000 个唯一查询摘要。试图找到引起这些冲突的查询组合就像大海捞针一样容易。
如果幸运的话,您可以根据满意的互斥体和信号量来猜测您正在寻找哪种查询。在这种情况下,争用的是专用于辅助索引的自适应哈希索引。因此,您知道感兴趣的查询必须使用辅助索引,并且查询执行的索引查找和索引修改次数越多,它就越有可能成为问题的一部分。在这种情况下,只读查询使用了两个辅助索引,这可以从清单 18-3 所示的查询计划中看出。
EXPLAIN
SELECT dept_name, MIN(salary) min_salary,
AVG(salary) AS avg_salary, MAX(salary) AS max_salary
FROM employees.departments
INNER JOIN employees.dept_emp USING (dept_no)
INNER JOIN employees.salaries USING (emp_no)
WHERE dept_emp.to_date = '9999-01-01'
AND salaries.to_date = '9999-01-01'
GROUP BY dept_no
ORDER BY dept_name
*************************** 1\. row ***************************
id: 1
select_type: SIMPLE
table: departments
partitions: NULL
type: index
possible_keys: PRIMARY,dept_name
key: PRIMARY
key_len: 16
ref: NULL
rows: 9
filtered: 100
Extra: Using temporary; Using filesort
*************************** 2\. row ***************************
id: 1
select_type: SIMPLE
table: dept_emp
partitions: NULL
type: ref
possible_keys: PRIMARY,dept_no,idx_concurrency_book_0
key: idx_concurrency_book_0
key_len: 19
ref: employees.departments.dept_no,const
rows: 9
filtered: 100
Extra: Using index
*************************** 3\. row ***************************
id: 1
select_type: SIMPLE
table: salaries
partitions: NULL
type: ref
possible_keys: PRIMARY,idx_concurrency_book_2
key: idx_concurrency_book_2
key_len: 7
ref: employees.dept_emp.emp_no,const
rows: 1
filtered: 100
Extra: Using index
3 rows in set, 1 warning (0.0009 sec)
Listing 18-3The query plan for the read-only query in the test
dept_emp和salaries表上的连接都是分别使用二级索引idx_concurrency_book_0和idx_concurrency_book_2来执行的。同样,读写连接执行的查询使用辅助索引;这是留给读者验证的一个练习。
调查完成后,您需要决定如何处理争议。
解决方案和预防措施
与之前的案例研究不同,通常没有直接的方法来解决和预防该问题。相反,您需要测试和验证各种可能的系统更改的效果。因此,解决方案和预防措施部分合并在一起。
-
完全禁用自适应哈希索引
-
增加分区的数量
-
在挂起线程之前增加旋转圈数
-
将工作负载拆分到不同的副本
这些选项将在本节的剩余部分讨论。
禁用自适应哈希索引
对于自适应散列索引的争用,最直接的解决方案是禁用该特性。在这样做之前,您需要考虑报告的争用是否真的是一个性能问题。记住,互斥和信号量等待本身并不是问题的标志;事实上,它们是 MySQL 的自然组成部分。一旦不能立即满足请求,自旋等待计数器就增加。如果查询在请求完成之前只等待几轮,这不一定是个问题。您可以查看每次等待的平均旋转次数,并使用它来估计等待时间。如图 18-3 所示。
图 18-3
共享和独占读写锁的平均每次等待旋转次数
该图显示,对于独占锁,平均而言,每次等待花费 80 到 100 轮等待。这很重要,因为每次轮询之间都有延迟(选项innodb_spin_wait_delay和innodb_spin_wait_pause_multiplier)。此外,默认情况下,在 30 轮之后(innodb_sync_spin_loops选项),InnoDB 会暂停线程,使其可用于其他目的,这使得再次唤醒查询的成本更高。对于共享锁,平均不到五个,因此更易于管理。
您还应该考虑使用自适应散列索引查找行和保存 B 树搜索的频率。与 B 树搜索相比,哈希索引查找速度更快,因此自适应哈希索引可以完成的搜索越多,开销就越大。InnoDB 有两个指标来跟踪 hash 索引的使用频率和 B 树的访问频率。此外,还有其他六个与自适应哈希索引相关的指标,但这些指标在默认情况下是禁用的(这些值包括测试之前完成的工作,因此会有所不同):
mysql> SELECT variable_name, variable_value AS value, enabled
FROM sys.metrics
WHERE type = 'InnoDB Metrics - adaptive_hash_index'
ORDER BY variable_name;
+------------------------------------------+----------+---------+
| variable_name | value | enabled |
+------------------------------------------+----------+---------+
| adaptive_hash_pages_added | 0 | NO |
| adaptive_hash_pages_removed | 0 | NO |
| adaptive_hash_rows_added | 0 | NO |
| adaptive_hash_rows_deleted_no_hash_entry | 0 | NO |
| adaptive_hash_rows_removed | 0 | NO |
| adaptive_hash_rows_updated | 0 | NO |
| adaptive_hash_searches | 51488882 | YES |
| adaptive_hash_searches_btree | 10904682 | YES |
+------------------------------------------+----------+---------+
8 rows in set (0.0097 sec)
这表明散列索引已经完成了超过 5100 万次搜索(adaptive_hash_searches),而使用 B 树需要的搜索不到 1100 万次。这给出了一个命中率
82.5%的命中率可能看起来不错,但是对于自适应散列索引来说,这可能(取决于工作负载)偏低。请记住,散列索引还会占用缓冲池中的内存。如果禁用自适应散列索引,该内存可用于缓存 B 树索引。您还需要考虑指标覆盖多长时间,以及散列索引的有用性是否有波动。对于后者,监控软件中的图表是查看一段时间内数据的好方法。图 18-4 显示了一个基于测试期间收集的指标的示例。
图 18-4
测试期间的自适应散列索引搜索指标
这里您可以看到,最初,自适应散列索引是有效的,大多数搜索都是使用散列索引完成的。然而,在测试的第 6 秒,adaptive_hash_searches指标开始直线下降,在 9 秒标记之后,直到测试接近结束,它没有超过每秒 250 个匹配。您还可以看到,这两者的总和在这段时间内比开始时低得多,这可能是由于争用导致整体查询性能下降。但是,您需要使用其他来源来确认是否是这种情况;这是作为练习留下的。
或者,您可以直接绘制命中率,如图 18-5 所示。
图 18-5
测试期间的自适应哈希索引命中率
这清楚地表明,最初,自适应散列索引非常有效,但随后就变得无用了。基于此,似乎有必要禁用自适应散列索引,例如,可以通过将innodb_adaptive_hash_index设置为OFF或0来做到这一点
SET GLOBAL innodb_adaptive_hash_index = OFF;
Query OK, 0 rows affected (0.1182 sec)
虽然您可以测试动态禁用散列索引,但是请注意,一旦您这样做,缓冲池中的散列索引就会被清除,因此如果您稍后重新启用该特性,您将需要重新构建散列。对于大型实例,自适应散列索引可能会使用 25 GiB 或更多内存,因此需要一段时间来重建。因此,当您在生产系统中禁用自适应散列索引时,您可能希望保持副本处于启用状态,这样,如果禁用innodb_adaptive_hash_index导致性能下降,您可以故障切换到副本。
Tip
最后,对于信号量争用问题,您将需要使用基准或在类似生产的环境中测试,或者通过使用不同设置的副本来验证您的更改的效果。虽然可以像在本讨论中一样对影响进行一些估计,但是相关部分之间的相互作用是复杂的,在测量之前,您无法确定总体影响。
虽然禁用自适应哈希索引是一个简单的解决方案,但是您可以考虑其他一些更改,这些更改可能允许您至少部分地继续使用自适应哈希索引。
增加哈希索引部分的数量
如果争用是由太多的连接命中同一个散列分区引起的,那么一个选项是增加自适应散列索引被分割成的部分的数量。这是通过innodb_adaptive_hash_index_parts选项完成的。没有直接的方法来确定增加散列索引部分的数量是否有帮助,尽管您可以查看 InnoDB monitor 输出中的INSERT BUFFER AND ADAPTIVE HASH INDEX部分,并查看每个部分中缓冲区的大小和数量,例如
mysql> SHOW ENGINE INNODB STATUS\G
...
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 13, seg size 15, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 3880 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
...
这是测试结束时的输出,您可以看到它主要是正在使用的部件之一(哪个部件可能会因您而异)。因此,在这种情况下,添加更多的散列索引部分可能没有帮助。在具有许多索引的更实际的生产使用中,您更有可能从更多的部件中受益。
其他解决方案
本节前面已经讨论过,这是一个问题,因此许多自旋等待被转换为操作系统等待。特别是如果您没有使用所有的 CPU,您可以考虑增加innodb_sync_spin_loops选项的值,以允许 InnoDB 持续轮询 rw 锁是否可用。这可以减少上下文切换的次数和总等待时间。
最后,您可以考虑将查询分为受益于自适应散列索引的查询和没有受益于自适应散列索引的查询,并将每组查询指向不同的副本。这样,您可以在启用了自适应哈希索引功能的副本上执行受益于该功能的查询,而在禁用了自适应哈希索引功能的副本上执行那些没有受益的查询。这显然主要是针对只读任务的解决方案。
摘要
本案例研究调查了自适应散列索引上信号量争用的一个例子。症状包括由 InnoDB monitor 的innodb_rwlock_% InnoDB metrics 和SEMAPHORES部分报告的等待次数增加,这是由于太多的查询需要对相同闩锁进行冲突访问。
与之前的大多数案例研究相比,本案例研究的设置更加复杂,并且使用 MySQL Shell 的concurrency_book模块可以轻松再现。本章的工作负载提示测试的各种设置,因此您可以尝试为您的系统调整测试。
调查开始时使用innodb_rwlock_%指标来确定争用何时成为问题。您可以查看原始指标和每次旋转等待的旋转圈数。然后使用 InnoDB 监控器和 mutex 监控器来确定自适应散列索引上的争用位置。最后,讨论了如何确定导致争用的工作负载。
当处理互斥和信号量争用时,解决方案通常不简单且不确定。对于自适应散列索引,最直接的选择是禁用它,但是在这之前,您需要考虑该特性的整体有效性,包括命中率。一种替代方法是将散列索引分成更多部分;然而,这只有在争用影响到几个现有分区时才有效。其他解决方案包括增加允许的旋转循环数量,以减少 InnoDB 暂停轮询的频率,以及使用具有不同配置的多个读取副本。
这就结束了 MySQL 并发世界的旅程,重点是锁和事务。请记住,熟能生巧,对于本书中讨论的话题来说尤其如此。本书的其余部分由两个附录组成,其中附录 A 包含性能模式表、InnoDB monitor 等的各种参考。附录 B 是 MySQL Shell 的concurrency_book模块的参考。
祝您继续 MySQL 并发性能之旅好运。