MySQL信号量等待日志阅读

2022-09-17 14:53:08 浏览数 (1)

MySQL信号量等待日志阅读

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

代码语言：c复制
--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中定义了两个宏:
代码语言：c复制
/* 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对应不同的取值状态就代表了加锁情况:

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

代码语言：c复制
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;
}
代码语言：c复制
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均不同:

加锁类型

amount

threshold

判断条件及加锁动作 If (lock_word > threshold) lock_word -= amount

s

1

0

x

X_LOCK_DECR

X_LOCK_HALF_DECR

sx

X_LOCK_HALF_DECR

X_LOCK_HALF_DECR

举个例子:

lock_word 为初始值X_LOCK_DECR，添加x锁时:

代码语言：c复制
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

代码语言：shell复制
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发。
  4. 步骤3a：每回合将调用PAUSE逻辑，这将导致CPU在X周期内进入PAUSE。
  5. 步骤3b：在每个回合后发布一次软检查，以确认是否有上述锁可用（busy-wait）。
代码语言：txt复制
* 如果可用，则旋转周期退出。步骤3c：再次尝试获取所需的锁。如果成功，则返回。（spins=1, rounds=M (M <= N), os-waits=0）如果失败，并且有一些待处理的回合（max = innodb_sync_spin_loops），则继续旋转。（如何中断循环并导致锁定失败。注意：并行由多个线程查看该锁。虽然在尝试获取该锁时，多个线程已收到有关锁可用性的信号，但其他线程却接过了该锁因此，该线程现在返回重试）。
  • 步骤3d：说一个线程现在完成了它的旋转等待轮，甚至现在它也没有获得锁。进一步旋转和浪费CPU周期没有任何意义。更好地放弃待处理的CPU周期，将其返回给OS，让OS调度做必要的事情。而且，由于所述线程现在要进入睡眠状态，因此应该在一些通用基础结构中注册自己，这将在有可用所述锁定时帮助其发回活动状态。
  • 步骤3e：将线程基础结构通过信号发回到Innodb活动状态的同步阵列基础结构中
代码语言：txt复制
* 所述线程通过在所述阵列中保留插槽来注册自身。
* 在开始等待之前，请再次尝试查看该锁是否可用。（因为预订可能很耗时，并且锁可能同时可用）。
* 如果仍然没有锁，则等待同步阵列基础结构发信号通知该线程。
* 此等待称为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

代码语言：shell复制
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

代码语言：shell复制
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
  2. 流程中，自旋循环35K次。
  3. 只有19K次(大约是自旋循环的一半)引起了OS-waits。
  4. 平均每个自旋周期也限制在777178/35943=21.62，这表明，对于每个自旋周期，平均有22轮PAUSE循环。
  5. Conclusion: 该Use-case表示中度竞争情况。

Use Case 3

代码语言：txt复制
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/
c++ 数据库 云数据库SQLServer sqlmysql 信号量等待

0 人点赞