1. 背景

产品 TMES
涉及模块 ldap-synchandler
问题描述 ldap-synchandler 执行 SQL 语句时，经常出现 “Lock wait timeout exceeded; try restarting transaction” 异常
Note ldap-synchandler 连接 DB 的 session 的事务隔离级别是：读提交。
意味着，每一条 SQL 执行完都会提交事务，并释放锁。

2. 问题追溯

2.1 Trace Log

  1. {
  2.     "log": "[2021/06/29 16:07:07,ldap-sync-handler,ERROR,] Thread-3 @GroupHandler.py:463 1205 (HY000): Lock wait timeout exceeded; try restarting transaction\nTraceback (most recent call last):\n  File \"/dirdataupload/scripts/SyncHandler/GroupHandler.py\", line 220, in doHandle\n    self.processDelUsers(delUsers)\n  File \"/dirdataupload/scripts/SyncHandler/GroupHandler.py\", line 598, in processDelUsers\n    self.cursor.execute(delete_sql, x)\n  File \"/usr/local/lib/python3.9/site-packages/mysql/connector/cursor.py\", line 551, in execute\n    self._handle_result(self._connection.cmd_query(stmt))\n  File \"/usr/local/lib/python3.9/site-packages/mysql/connector/connection.py\", line 490, in cmd_query\n    result = self._handle_result(self._send_cmd(ServerCmd.QUERY, query))\n  File \"/usr/local/lib/python3.9/site-packages/mysql/connector/connection.py\", line 395, in _handle_result\n    raise errors.get_exception(packet)\nmysql.connector.errors.DatabaseError: 1205 (HY000): Lock wait timeout exceeded; try restarting transaction\n[2021/06/29 16:07:07,ldap-sync-handler,WARNING,] Thread-3 @handler.py:319 Processed the user groups failed\n"
  3. }
  1. {
  2.     "log": "[2021/07/02 16:53:05,ldap-sync-handler,ERROR,] Thread-3 @RecipientHandler.py:75 1205 (HY000): Lock wait timeout exceeded; try restarting transaction\nTraceback (most recent call last):\n  File \"/dirdataupload/scripts/SyncHandler/RecipientHandler.py\", line 73, in doHandle\n    self.cursor.execute(self.sql_addChangedDomain, (domainId, domainName))\n  File \"/usr/local/lib/python3.9/site-packages/mysql/connector/cursor.py\", line 551, in execute\n    self._handle_result(self._connection.cmd_query(stmt))\n  File \"/usr/local/lib/python3.9/site-packages/mysql/connector/connection.py\", line 490, in cmd_query\n    result = self._handle_result(self._send_cmd(ServerCmd.QUERY, query))\n  File \"/usr/local/lib/python3.9/site-packages/mysql/connector/connection.py\", line 395, in _handle_result\n    raise errors.get_exception(packet)\nmysql.connector.errors.DatabaseError: 1205 (HY000): Lock wait timeout exceeded; try restarting transaction\n"
  3. }

2.2 Findings

根据 log 发现，ldap-synchandler 的 GroupHandler.py，在执行下述 sql 时，Lock wait timeout：

  1. insert ignore into tb_changed_domain(domain_id,domain_name,operate_type,create_time) values (%s, %s, 3, NOW());
  3. delete from tb_ldap_group_recipient where ldap_id IN (select a.ldap_id from tb_account_ldap a, tb_account_ldap b where a.account_id = b.account_id and b.ldap_id=%s) and domain_id=%s and user_part in (%s) and ldap_rs_mask = '%s';

涉及的 table 有：tb_changed_domain 和 tb_ldap_group_recipient。

3. 查看 Lock wait timeout

  1. mysql> SHOW VARIABLES LIKE 'innodb_lock_wait_timeout';
  2. +--------------------------+-------+
  3. | Variable_name            | Value |
  4. +--------------------------+-------+
  5. | innodb_lock_wait_timeout | 120   |
  6. +--------------------------+-------+
  8. mysql> SHOW global  VARIABLES LIKE 'innodb_lock_wait_timeout';
  9. +--------------------------+-------+
  10. | Variable_name            | Value |
  11. +--------------------------+-------+
  12. | innodb_lock_wait_timeout | 120   |
  13. +--------------------------+-------+

发现都是 2 min。

4. 分析 tb_ldap_group_recipient 的 SQL

查看 tb_ldap_group_recipient 的相关的这条 SQL 的执行计划：

  1. explain delete from tb_ldap_group_recipient where ldap_id IN (select a.ldap_id from tb_account_ldap a, tb_account_ldap b where a.account_id = b.account_id and b.ldap_id=11) and domain_id=217971 and user_part in ('june_zhu', 'testgroup', 'shayne', 'test2', 'test123', ) and ldap_rs_mask = '9A0A160DC5AC7C9CADEFA48A20D467CF2A5EE6C1';

结果如下：

  1. *************************** 1. row ***************************
  2.            id: 1
  3.   select_type: DELETE
  4.         table: tb_ldap_group_recipient
  5.    partitions: p0,p1,p2,p3,p4,p5,p6,p7,p8,p9,p10,p11,p12,p13,p14,p15,p16,p17,p18,p19,p20,p21,p22,p23,p24,p25,p26,p27,p28,p29,p30,p31,p32,p33,p34,p35,p36,p37,p38,p39,p40,p41,p42,p43,p44,p45,p46,p47,p48,p49,p50,p51,p52,p53,p54,p55,p56,p57,p58,p59,p60,p61,p62,p63,p64,p65,p66,p67,p68,p69,p70,p71,p72,p73,p74,p75,p76,p77,p78,p79,p80,p81,p82,p83,p84,p85,p86,p87,p88,p89,p90,p91,p92,p93,p94,p95,p96,p97,p98,p99,p100,p101,p102,p103,p104,p105,p106,p107,p108,p109,p110,p111,p112,p113,p114,p115,p116,p117,p118,p119,p120,p121,p122,p123,p124,p125,p126,p127,p128,p129,p130,p131,p132,p133,p134,p135,p136,p137,p138,p139,p140,p141,p142,p143,p144,p145,p146,p147,p148,p149,p150,p151,p152,p153,p154,p155,p156,p157,p158,p159,p160,p161,p162,p163,p164,p165,p166,p167,p168,p169,p170,p171,p172,p173,p174,p175,p176,p177,p178,p179,p180,p181,p182,p183,p184,p185,p186,p187,p188,p189,p190,p191,p192,p193,p194,p195,p196,p197,p198,p199,p200,p201,p202,p203,p204,p205,p206,p207,p208,p209,p210,p211,p212,p213,p214,p215,p216,p217,p218,p219,p220,p221,p222,p223,p224,p225,p226,p227,p228,p229,p230,p231,p232,p233,p234,p235,p236,p237,p238,p239,p240,p241,p242,p243,p244,p245,p246,p247,p248,p249,p250,p251,p252,p253,p254,p255
  6.          type: ALL
  7. possible_keys: NULL
  8.           key: NULL
  9.       key_len: NULL
  10.           ref: NULL
  11.          rows: 109
  12.      filtered: 100.00
  13.         Extra: Using where
  14. *************************** 2. row ***************************
  15.            id: 2
  16.   select_type: DEPENDENT SUBQUERY
  17.         table: b
  18.    partitions: NULL
  19.          type: const
  20. possible_keys: PRIMARY
  21.           key: PRIMARY
  22.       key_len: 4
  23.           ref: const
  24.          rows: 1
  25.      filtered: 100.00
  26.         Extra: NULL
  27. *************************** 3. row ***************************
  28.            id: 2
  29.   select_type: DEPENDENT SUBQUERY
  30.         table: a
  31.    partitions: NULL
  32.          type: eq_ref
  33. possible_keys: PRIMARY
  34.           key: PRIMARY
  35.       key_len: 4
  36.           ref: func
  37.          rows: 1
  38.      filtered: 10.00
  39.         Extra: Using where
  40. 3 rows in set (0.00 sec)

可以看到，这条 SQL：

  • 对 tb_ldap_group_recipient 的执行计划的 type 是 ALL，意味着，需要进行 全表扫描。
  • delete 操作，说明需要申请 表锁。

异常的原因是，执行这条语句时，申请 tb_ldap_group_recipient 的表锁超时。
而第 3 点已经查了设置的事务等待 lock 的时间是 2 min。

5. 分析 lock 原因

那么，什么情况会导致申请表锁超时？
这个表被别的事务加了 写锁，或者 读锁，或者意向写锁，或者意向读锁，且 2 min 都没有释放。

对表加 写锁：SQL 执行计划的 type 为 ALL，SQL 本身为 update，insert，delete，或者 select … for update。 对表加 读锁：SQL 执行计划的 type 为 ALL，SQL 本身为 select … lock in share mode。 对表加 意向写锁：对表中某一行或者几行加 写锁。 对表加 意向读锁：对表中某一行或者几行加 读锁。 NOTE：普通 select 不加任何锁。

我们代码中的 SQL，基本没有写成 select … lock in share mode，或者是 select … for update。

除了 rest api： select id from tb_validrecipient where domain_id=:domain_id for update

所以，肯定是有对 tb_ldap_group_recipient 的 delete，insert，update 操作，并且在一个长事务里。

使用表名“tb_ldap_group_recipient”，作为关键字搜索代码仓库，发现只有四处对 tb_ldap_group_recipient 加写锁的地方：

仓库 SQL 分析
ldap-synchandler delete from tb_ldap_group_recipient where ldap_id IN (select a.ldap_id from tb_account_ldap a, tb_account_ldap b where a.account_id = b.account_id and b.ldap_id=%s) and group_internal_id=%s and ldap_rs_mask = %s limit %s; ldap-synchandler 设置了 session 的事务隔离级别为 读提交，并且设置了 auto-commit —> 每条 SQL 语句都相当于会自动提交事务。

因此，这里的语句不会造成长事务导致锁无法释放的场景。
delete from tb_ldap_group_recipient where ldap_id IN (select a.ldap_id from tb_account_ldap a, tb_account_ldap b where a.account_id = b.account_id and b.ldap_id=%s) and domain_id=%s and user_part in (%s) and ldap_rs_mask = ‘%s’；
delete from tb_ldap_group_recipient where ldap_id IN (select a.ldap_id from tb_account_ldap a, tb_account_ldap b where a.account_id = b.account_id and b.ldap_id=%s) and ldap_rs_mask in (‘%s’) and last_modified_time < ‘%s’ limit %s；
insert into tb_ldap_group_recipient (ldap_id, user_part, domain_id, group_internal_id, first_name, middle_name, last_name, title, last_modified_time, ldap_rs_mask) values(%s, %s, %s, %s, %s, %s, %s, %s, NOW(), %s) ON DUPLICATE KEY UPDATE last_modified_time = NOW(), first_name=values(first_name), middle_name=values(middle_name), last_name=values(last_name), title=values(title)；
hes-migration-tool delete from tb_ldap_group_recipient where domain_id = %s; 这里的事务都很快 commit，应该不至于 2 min 执行不完。
insert into tb_ldap_group_recipient (ldap_id, user_part, domain_id, name, is_primary, group_internal_id, first_name, middle_name, last_name, title) values (%s, ‘%s’, %s, ‘%s’, ‘%s’, ‘%s’, ‘%s’, ‘%s’, ‘%s’, ‘%s’);
cross-site-migration-tool insert into tb_ldap_group_recipient( … ) values ( … ) ; cross-site-migration-tool 几乎不运行，不可能会是 lock 的原因。
uiserver update tb_ldap_group_recipient set model_status = 1 where id in ( … );
update tb_ldap_group_recipient set model_status = 0 where id in ( … );		 这两个 SQL 是在 BECDao 执行的，追溯一下是在ModelStatusUpdater 调用的，每 5 分钟调用一次。
下图是 ModelStatusUpdater 的调用关系：

ModelStatusUpdater (1).svg

上图可见，对所有 account 的操作，包括 REST API 请求，tb_ldap_group_recipient 的更新，tb_changed_domain 的 insert，都在一个长事务里。

image.png
此处可以看出，一次未成功执行未完成的操作的执行时间超过 3 min。

查 其他成功执行的 log 发现，每执行一次，需要 6 min 左右。
而此处事务的隔离级别为：可重复读。
意味着，一旦某一行或者表被锁着，直到事务 commit，锁才会被释放。

再分析这条 update 的 SQL：

  1. mysql> explain update tb_ldap_group_recipient set model_status = 1 where id in (1,20000000)\G
  2. *************************** 1. row ***************************
  3.            id: 1
  4.   select_type: UPDATE
  5.         table: tb_ldap_group_recipient
  6.    partitions: p0,p1,p2,p3,p4,p5,p6,p7,p8,p9,p10,p11,p12,p13,p14,p15,p16,p17,p18,p19,p20,p21,p22,p23,p24,p25,p26,p27,p28,p29,p30,p31,p32,p33,p34,p35,p36,p37,p38,p39,p40,p41,p42,p43,p44,p45,p46,p47,p48,p49,p50,p51,p52,p53,p54,p55,p56,p57,p58,p59,p60,p61,p62,p63,p64,p65,p66,p67,p68,p69,p70,p71,p72,p73,p74,p75,p76,p77,p78,p79,p80,p81,p82,p83,p84,p85,p86,p87,p88,p89,p90,p91,p92,p93,p94,p95,p96,p97,p98,p99,p100,p101,p102,p103,p104,p105,p106,p107,p108,p109,p110,p111,p112,p113,p114,p115,p116,p117,p118,p119,p120,p121,p122,p123,p124,p125,p126,p127,p128,p129,p130,p131,p132,p133,p134,p135,p136,p137,p138,p139,p140,p141,p142,p143,p144,p145,p146,p147,p148,p149,p150,p151,p152,p153,p154,p155,p156,p157,p158,p159,p160,p161,p162,p163,p164,p165,p166,p167,p168,p169,p170,p171,p172,p173,p174,p175,p176,p177,p178,p179,p180,p181,p182,p183,p184,p185,p186,p187,p188,p189,p190,p191,p192,p193,p194,p195,p196,p197,p198,p199,p200,p201,p202,p203,p204,p205,p206,p207,p208,p209,p210,p211,p212,p213,p214,p215,p216,p217,p218,p219,p220,p221,p222,p223,p224,p225,p226,p227,p228,p229,p230,p231,p232,p233,p234,p235,p236,p237,p238,p239,p240,p241,p242,p243,p244,p245,p246,p247,p248,p249,p250,p251,p252,p253,p254,p255
  7.          type: range
  8. possible_keys: id
  9.           key: id
  10.       key_len: 4
  11.           ref: const
  12.          rows: 2
  13.      filtered: 100.00
  14.         Extra: Using where
列名 值 描述
type range 索引范围扫描，对索引的扫描开始于某一点，返回匹配值域的行。
key id MySQL在查询中实际使用的索引

由此，我们可以得出，这条 sql 语句用了 主键索引。
而由于这条语句是 update 操作，因此在 某几行索引加的是 写锁——排他锁。

根据 InnoDB 的设计，当对表的某一行或者几行加写锁前，会先对表加意向写锁。
此时，别的事务对此表的写锁申请，均会被阻塞。

而 tb_ldap_group_recipient 的表的意向写锁，要等到事务提交，才会释放。换句话说，这个意向写锁可能会持续 6 min。
这应该就是 ldap-synchandler 对 tb_ldap_group_recipient 写锁申请 timeout 的原因了。

6. 解决

6.1 思路

分 2 步走：

  • 首先，将 tmasewrapper 更新状态的周期改为 1 hour；
  • 其次，将单个 account 的处理抽出来放在一个 transaction 里。

对所有 account 操作的 function：

  1. BECService.updateWritingStyleModelStatus()

这个 function 会调用对每个 account 操作的 function：

  1. BECService.updateModelStatus(acctID)

6.2 错误做法

通过Spring 事务的传播特性，将

  • updateWritingStyleModelStatus() 的 propagation 改成 Propagation.NEVER。
  • updateModelStatus(acctID) 的 propagation 保持 Propagation.REQUIRED。

这样做的结果是，updateModelStatus(acctID) 也没有运行在事务里。
所以是不可行的。

原因是，Spring 只有在类之间的方法调用，才会采用动态代理，创建代理对象。而 Spring 的事务，正是通过注解的方式，创建代理对象实现的。

6.2 正确做法

将 updateWritingStyleModelStatus() 方法抽到另一个类中，且此方法不加 @Transactional 注解。