MySQL信号量等待日志阅读

MySQL中偶尔会遇到Hang住问题，show engine innodb status 中会显示大量的如下信息:

--Thread 140477271320320 has waited at ibuf0ibuf.cc line 3439 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7fc5a5faa520 created in file buf0buf.cc line 1460
a writer (thread id 140477635114752) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: fffffffff0000000
Last time read locked in file ibuf0ibuf.cc line 4552
Last time write locked in file /dba/app/mysql_home/5.7.19/storage/innobase/ibuf/ibuf0ibuf.cc line 406
2020-11-25T09:33:15.302783+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140477265372928 has waited at btr0cur.cc line 976 for 241.00 seconds the semaphore:
SX-lock on RW-latch at 0x7fc3189b57b0 created in file dict0dict.cc line 2687
a writer (thread id 140477291595520) has reserved it in mode  SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time read locked in file btr0cur.cc line 1008
Last time write locked in file /dba/app/mysql_home/5.7.19/storage/innobase/btr/btr0cur.cc line 976

这种信息比较难以让人理解，此文将分析如何阅读这些信息

信息解读

从上面内容可以得到如下信息:

• Thread 140477271320320 在  ibuf0ibuf.cc line 343 添加锁时发生了等待，等待时间是241 s

• 这个RW-latch 创建在 buf0buf.cc line 1460

• a writer (thread id 140477635114752) has reserved it in mode  exclusive ， 140477635114752这个线程，作为写者已经获取到了这个RW-latch的锁，并且是独占方式

• lock_word: fffffffff0000000 最重要的信息
  关于lock_word 需要特殊说明其含义:
  MySQL中系统层面的锁，有RW-latch，mutex，等，这里提到的都是RW-latch。lock_word代表了这个latch上的持有锁情况。RW-LOCK的加锁都是通过对lock_word减去某些值来实现加锁，解锁与其相反。MySQL中定义了两个宏:

/* We decrement lock_word by X_LOCK_DECR for each x_lock. It is also the
start value for the lock_word, meaning that it limits the maximum number
of concurrent read locks before the rw_lock breaks. */
/* We decrement lock_word by X_LOCK_HALF_DECR for sx_lock. */
#define X_LOCK_DECR        0x20000000
#define X_LOCK_HALF_DECR    0x10000000

lock_word的初始值为X_LOCK_DECR，每次添加x锁时原子递减X_LOCK_DECR，每次添加S锁时原子递减1。每次添加SX锁时递减X_LOCK_HALF_DECR。如果读写锁支持递归写，那么第一个递归写锁加锁成功时，lock_word 依然原子递减X_LOCK_DECR，而后续的递归写锁加锁成功时，lock_word 只是原子递减1。

The status of a rw_lock is held in lock_word. The initial value of lock_word is
X_LOCK_DECR. lock_word is decremented by 1 for each s-lock and by X_LOCK_DECR
or 1 for each x-lock

lock_word对应不同的取值状态就代表了加锁情况:

这里需要结合加锁函数去看:

rw_lock_x_lock_low(rw_lock_t*  lock, ulint pass, const char* file_name, ulint line) {

  // 如果lock_word>X_LOCK_HALF_DECR，尝试将lock_word减少X_LOCK_DECR，代表了X锁只能添加一次
  // 如果成功，则至少预定自己为下一个写锁的持有者，返回true，否则返回false
  if (rw_lock_lock_word_decr(lock, X_LOCK_DECR, X_LOCK_HALF_DECR)) {

    // 预定自己为下一个写锁持有者，此时lock_word<=0，last_x_file_name:last_x_line 为上一个写锁持有者的上锁位置
    // 将自己的线程标识写入writer_thread，
    rw_lock_set_writer_id_and_recursion_flag(lock, !pass);)

    // 如果lock_word<0，说明有线程持有读锁，必须等待读锁释放
    // 阻塞直到 lock_word==0, 
    rw_lock_x_lock_wait(lock, pass, 0, file_name, line);

  } else {
    ......
  }

  // 成功获得写锁，last_x_file_name:last_x_line指向加锁的位置
  lock->last_x_file_name = file_name;
  lock->last_x_line = (unsigned int) line;

  return true;
}

rw_lock_lock_word_decr(
/*===================*/
    rw_lock_t*  lock,       /*!< in/out: rw-lock */
    ulint       amount,     /*!< in: amount to decrement */
    lint        threshold)  /*!< in: threshold of judgement */
{
#ifdef INNODB_RW_LOCKS_USE_ATOMICS
    lint local_lock_word;

    os_rmb;
    local_lock_word = lock->lock_word;
    while (local_lock_word > threshold) { 
        if (os_compare_and_swap_lint(&lock->lock_word,
                         local_lock_word,
                         local_lock_word - amount)) {
            return(true);
        }
        local_lock_word = lock->lock_word;
    }
    return(false);
#else /* INNODB_RW_LOCKS_USE_ATOMICS */
    bool success = false;
    mutex_enter(&(lock->mutex));
    if (lock->lock_word > threshold) {
        lock->lock_word -= amount;
        success = true;
    }
    mutex_exit(&(lock->mutex));
    return(success);
#endif /* INNODB_RW_LOCKS_USE_ATOMICS */
}

施加不同的锁时，传入的amount和threshold均不同:

举个例子:
lock_word 为初始值X_LOCK_DECR，添加x锁时:

while (local_lock_word > threshold) { 
        if (os_compare_and_swap_lint(&lock->lock_word,
                         local_lock_word,
                         local_lock_word - amount)) {
            return(true);
        }
        local_lock_word = lock->lock_word;
    }
经过上面运算后lock_word = 0 即代表加X锁成功

此问题中lock_word: fffffffff0000000 = – 268435456即- X_LOCK_HALF_DECR，代表添加了X和SX锁，
线程140477271320320再次申请S锁时就发生了等待。

• Last time read locked in file ibuf0ibuf.cc line 4552 最后读取锁的位置

• Last time write locked in file /dba/app/mysql_home/5.7.19/storage/innobase/ibuf/ibuf0ibuf.cc line 406 最后写入锁的位置

但是这两个并一定就是a writer (thread id xxx)持有的，需要配合lock_word或者根据状态:
has reserved it in mode  exclusive
has reserved it in mode  wait exclusive
来判断

RW-LATCH INFO

Total number of rw-locks 393385
OS WAIT ARRAY INFO: reservation count 585479
OS WAIT ARRAY INFO: signal count 112559
RW-shared spins 0, rounds 530324, OS waits 385606
RW-excl spins 0, rounds 1265658, OS waits 41898
RW-sx spins 67610, rounds 2015448, OS waits 66228
Spin rounds per wait: 530324.00 RW-shared, 1265658.00 RW-excl, 29.81 RW-sx

关于spin lock流程如下:

1. 尝试获得rw-lock锁:

• 成功 ， 直接返回

• 不成功，进入循环

2. 开始循环

3. 开始旋转N轮。（这里N由innodb_sync_spin_loops定义和控制）。默认值为30发。

• 步骤3a：每回合将调用PAUSE逻辑，这将导致CPU在X周期内进入PAUSE。

• 步骤3b：在每个回合后发布一次软检查，以确认是否有上述锁可用（busy-wait）。

• 如果可用，则旋转周期退出。

• 步骤3c：再次尝试获取所需的锁。

• 如果成功，则返回。（spins=1, rounds=M (M <= N), os-waits=0）

• 如果失败，并且有一些待处理的回合（max = innodb_sync_spin_loops），则继续旋转。（如何中断循环并导致锁定失败。注意：并行由多个线程查看该锁。虽然在尝试获取该锁时，多个线程已收到有关锁可用性的信号，但其他线程却接过了该锁因此，该线程现在返回重试）。

• 步骤3d：说一个线程现在完成了它的旋转等待轮，甚至现在它也没有获得锁。进一步旋转和浪费CPU周期没有任何意义。更好地放弃待处理的CPU周期，将其返回给OS，让OS调度做必要的事情。而且，由于所述线程现在要进入睡眠状态，因此应该在一些通用基础结构中注册自己，这将在有可用所述锁定时帮助其发回活动状态。

• 步骤3e：将线程基础结构通过信号发回到Innodb活动状态的同步阵列基础结构中

• 所述线程通过在所述阵列中保留插槽来注册自身。

• 在开始等待之前，请再次尝试查看该锁是否可用。（因为预订可能很耗时，并且锁可能同时可用）。

• 如果仍然没有锁，则等待同步阵列基础结构发信号通知该线程。

• 此等待称为OS等待，进入此循环现在将导致OS等待计数增加。

• 步骤3f：说该线程由同步阵列基础结构发信号通知等待事件。重试以获得所需的锁。

• 如果成功，则返回。（spins=1, rounds=N, os-waits=1）

• 如果失败，则整个循环从旋转逻辑重新启动（返回到第3步，并将回合计数重新初始化为0）。注意：spin次数不会重新增加。

PAUSE 逻辑
K = {random value from between (0 – innodb_spin_wait_delay) * innodb_spin_wait_pause_multiplier}
调用底层 PAUSE 指令 K 次.

Use Case 1

RW-shared spins 338969, rounds 20447615, OS waits 592941
RW-excl spins 50582, rounds 1502625, OS waits 56124
RW-sx spins 12583, rounds 360973, OS waits 10484
Spin rounds per wait: 60.32 RW-shared, 29.71 RW-excl, 28.69 RW-sx

让我们分析一下共享自旋的情况:

1. RW-shared spins 338969, rounds 20447615, OS waits 592941

• 在头一次尝试中，用了338K 次仍未获取到锁，迫使线程进入自旋锁状态(spin-lock)。

• 在每个自旋周期内，执行了60轮PAUSE周期（因此，所述自旋周期执行了2次）。
  OS-waits/spins = 592/338 = 1.75表明大部分被分流进入了OS-wait（PAUSE的延迟不够）。

• 表明对于大多数自旋周期，单一的操OS-wait是不够的，因此这种操作是在重复进行的。

• Conclusion: 该Use-case是高竞争情况。而且，诸如PAUSE循环无法产生所需的延迟来获得锁，导致每个自旋周期产生如此之多的PAUSE循环。

Use Case 2

RW-shared spins 35943, rounds 777178, OS waits 19051
RW-excl spins 4269, rounds 121796, OS waits 4164
RW-sx spins 13407, rounds 321954, OS waits 7346
Spin rounds per wait: 21.62 RW-shared, 28.53 RW-excl, 24.01 RW-sx

让我们分析一下共享自旋的情况:

1. RW-shared spins 35943, rounds 777178, OS waits 19051

• 流程中，自旋循环35K次。

• 只有19K次(大约是自旋循环的一半)引起了OS-waits。

• 平均每个自旋周期也限制在777178/35943=21.62，这表明，对于每个自旋周期，平均有22轮PAUSE循环。

• Conclusion: 该Use-case表示中度竞争情况。

Use Case 3

RW-shared spins 39578, rounds 424553, OS waits 7329
RW-excl spins 5828, rounds 78225, OS waits 1341
RW-sx spins 11666, rounds 67297, OS waits 449
Spin rounds per wait: 10.73 RW-shared, 13.42 RW-excl, 5.77 RW-sx

• 流程中自旋循环39K次。

• 只有7K(约占自旋循环的20%) 导致OS-waits。

• 每自旋周期平均数也限制为424553/39578=10。

• Conclusion: 该Use-case表示低竞争情况。

参考资料

1. 《数据库事务处理的艺术: 事务管理与并发控制》-李海翔老师

2. https://mysqlonarm.github.io/Understanding-InnoDB-rwlock-stats/

3. http://mysql.taobao.org/monthly/2020/03/07/