vlambda博客
学习文章列表

内核分析之mysql诡异重启故障

1.前言
如果mysql实例连接数满掉了,脑袋里蹦出的第一个想法是先增大max_connection,但有种情况,解决方案却是减少max_connection。

2.冰中火
看看这张图:


各位看完后一定很愤怒,CPU Util,CPU Load,磁盘IO和网络IO指标都很低,毫无性能压力的服务器指标,有啥好看的(其实是有指标异常的)。

冰块中的火
别急,在毫无波澜的服务器上,mysql实例内部已经翻山倒海了,请看下图:

内核分析之mysql诡异重启故障

有接近三万的活动连接,所有的连接都是执行非常简单的单条insert语句。但是,这些sql语句,都已经执行了十多分钟还未结束。而且再过不到十分钟,mysql实例将实现自我涅槃(自动重启)。

简直就是在冰块中熊熊燃烧着一团火。
 
3.故障起因
某日,业务开发突然反馈,应用出现大量无法建立新连接的报错。

连接数爆满
登录上mysql实例发现,最大3万的连接数,已经满的不能再满了。
  • 实例中全部都是活动连接

  • 大量执行简单的单行insert

  • 没有行/表锁阻塞


如同上图中所示,所有的sql语句执行TIME都在增大,就是不见有sql执行完成。

简单点来说,就是3万个sql卡在实例中了

失效的kill
怎么办?
和业务开发沟通后,kill掉所有的sql。然,悲剧发生了,kill也卡住了,所有的连接都显示Killed状态,依旧顽固的赖在实例里,如下图:

内核分析之mysql诡异重启故障

涅槃的实例
20多分钟后,mysql实例突然自动重启了
整个过程中,服务器性能指标都很正常,所以服务器层面没有任何报警出现。
简单来讲,就是服务器说我很轻松,很happy, mysql实例说AWSL
 
4.初步调查
瞬间暴涨到3万个并发连接,一定是应用突然进来了大量访问,开发也确认了,业务量是有所上升。
我司针对java和C#开发了sdk和连接中间件,但是这个业务的应用是C写的,无法接入中间件,所以数据库的连接数会一直涨到满。


高配服务器低性能?
普通的ssd服务器,几万qps的插入肯定是没问题的,这么好的机器(112核CPU,256G内存,磁盘PCIE SSD),几十万的qps应该不在话下吧,好歹PCIE SSD比普通ssd磁盘至少有10倍的读写提升,难道就撑不住这些业务量吗?

思维误区
等等,这里存在一个思维误区,升级服务器配置是否能提高数据库的吞吐量?对于oracle来说,是毋容置疑的,但对于mysql,是不是这样的呢?
 
先调查一下
 mysql的error log里有线索:
内核分析之mysql诡异重启故障
InnoDB: Error: semaphore wait has lasted> 600 seconds
这么明显的提示,啥都别说了,翻源码。

自保(自杀)机制
Srv0srv.cc文件中1750行(mysql版本为5.6.31),后台线程会循环检查原子锁的等待时间,如果连续10次检测超时,则自杀
其实看到semaphore,基本上就知道原子锁是脱不了干系了。
 
网上搜索一下解决方案:
  • 修改内核参数

  • 禁用自适应哈希索引。


 
5.如果事情有那么简单就好了
这个方案先要测一下,否则不能直接在线上执行,心脏没有那么大。
 
故障复现
首先在其他环境复现这个问题。
没想到很容易就复现了,写了一个30进程3万线程的并发insert程序,成功复现了上面的问题。直接排除掉服务器硬件和操作系统因素
然后测试了一下这个解决方案,并没有啥用。看来事情没那么简单,要深入调查一下了。
 
深入调查
接着继续调查其他线索。
在实例重启前,mysql将大量的连接信息dump到了error log中,类似这样的:


里面直截了当的告诉你连接阻塞在了哪个代码行里。

分析日志
由于输出的日志实在太多(大概1个G),人工去统计显然不现实,只好写个脚本进行分析统计。
统计后,去源码里跟踪一下这些方法的链路,发现:
  • 耗时第一个多的是mtr_s_lock方法,这个是对B树操作的原子锁

  • 耗时第二多的是rw_lock_s_lock_func方法,这个是innodb的latch原子锁


 
systemtap
然,error log里面只是采样数据,真实情况是不是这样的呢?真正原因是否能采样出来?是否能用其他手段,来印证采样的准确性呢?
想来想去,看来要对mysql的insert源码做全链路分析了。
那就要用到大名鼎鼎的systemtap了(也就是centos版的dtrace,研究oracle内核的最喜欢用dtrace了)。

源码验证
思路是,将mysql的insert的源码流程,划分成多个子模块,跑压力的同时用systemtap来统计模块耗时。然后拆分其中耗时的模块,进行更细粒度的耗时统计。循环几次,最终找到最耗时的几个函数。
按照上面的思路,多次测试过后发现,不仅上面两个锁很耗时,还有release_lock方法耗时也非常厉害,这个是MetaData的原子锁
 
6.原理分析
从上面的调查可以发现,问题就出在原子锁上。
mysql的原子锁类型很多,但基本就分两类:
  • 一类是不会回旋的锁,

  • 一类是带回旋的锁(相当于oracle里的latch)。


show engine innodb status
在show engine innodb status中的SEMAPHORES模块,可以看到innodb的回旋锁的概况。但它仅仅是概况,显然信息是远远不够的。实际上, mysql对原子锁的信息采集和记录实在太少了 ,你根本就无法知道当前连接卡在了哪里,它在等待什么。
相比之下,oracle就做的非常完善,以前通过oracle详细的event信息,顺利找到了在AMM下shared pool把buffercache内存给挤光了的故障原因。

被忽略的csw
原子锁的竞争,让mysql连接都卡住,甚至kill不掉(kill也需要竞争原子锁),这个很容易理解,为啥服务器性能指标没有任何异常呢?
其实是有异常,不过不在我们经常关注的那些指标上,而是在csw上,即上下文切换(Context Switch)
这个指标非常的高,有上下文切换,说明有线程切换,有线程切上来,就说明有线程切下去(休眠),这 都是原子锁竞争的表现

模拟高并发竞争
这些都串起来了,但还差一点需要验证,是否大量的原子锁竞争,只会导致服务器的csw指标异常,而其他指标毫无波澜呢。
这就需要自己动手写代码了,撸了一个简单的C,代码如下:


int NUM_THREADS=30000;
void print_msg(char *ptr);
int sum = 0
pthread_mutex_t sum_mutex;
int main()
{
   pthread_t tids[NUM_THREADS];
   int i;
   char *msg="do sth";
   char s[10];
   pthread_mutex_init (&sum_mutex, NULL);
   for(i = 0; i < NUM_THREADS; i++)
    {
       sprintf(s, "%d", i);
       char *element_s=(char*)malloc(strlen(msg)+strlen(s)+1);
       sprintf(element_s,"%.*s%.*s",strlen(msg),msg,strlen(s),s);
       int ret = pthread_create(&tids[i],NULL, (void *)(&print_msg),(void *)element_s);
       if (ret != 0)
       {
           printf("pthread_create error: error_code=%d\n", ret);
       }
    }
   pthread_exit(NULL);
   pthread_mutex_destroy(&sum_mutex);
}
void print_msg(char *ptr)
{
int i;
for(i = 0; i < 10000000; i++)
{
   int id=pthread_self();
   printf("---Thread ID: %x---\n",id);
   pthread_mutex_lock (&sum_mutex);
   sum++;
   printf("sum=%d\n",sum);
   pthread_mutex_unlock (&sum_mutex);
   printf("%s\n",ptr);
}
}


代码描述 

这段代码起了3万个线程,一起竞争原子锁。运行结果很喜人,除了csw指标上去了,其他指标基本没变化。这就解释了上面mysql实例内部原子锁大量竞争阻塞,而服务器没有任何报警的原因。
 
7.减少竞争者
之所以会有这么大量的原子锁竞争,是竞争者太多了,那么, 减少最大连接数,是不是就能减少原子锁竞争呢?

减少竞争
  • 将max_connection改成1.5万,跑了下压力,发现insert语句依旧卡着,说明竞争依旧很激烈,但是,不再出现自动重启的现象了,而且当应用停止后,这些残留的sql会慢慢的执行完。

  • 将max_connection改成3000,发现insert语句基本上2分钟执行完,竞争已经减轻很多了。

  • 将max_connection改成300,语句执行毫无压力,但明显没有发挥出服务器的真正实力


音障
看来减少竞争者是有效果的。 这个很容易理解,有竞争者就有等待者,就会存在等待者队列。这些等待者要么直接休眠,要么回旋后休眠,最后会被锁释放者一起唤醒,再进行竞争。想象一下, 几万个人同时抢一个卫生间,是不是很崩溃 。。。
但是连接数少了,服务器性能没有充足发挥,连接数多了,并发控制成本就越来越大。如同风阻一样,车速低的时候可以忽视风阻,随着车速增加,大量的能量消耗在了对付风阻上了,而当到达了音速, 音障横空出世
这就是为什么, 随着mysql并发数增加,性能呈上升趋势,而到达一定的并发数后,性能就开始下降

平衡的艺术
如何选取合适的连接数,在并发和并发控制中,发挥服务器最优性能,这简直就是个平衡的艺术。而且不同服务器的最优并发连接数肯定是不一样的,这就需要写一个通用的自动化测试脚本了。
不过,先对mysql5.7和mysql8.0进行测试,看看这两个版本是否也会出现同样的问题。
   
8.扩展测试
  • mariadb10.0.24


首先对mariadb10.0.24测试一下,测试原因是我司大量的使用这个版本的mysql。结果和mysql5.6.31一样, 3万个并发毫无悬念的就挂了

  • mysql5.7.30 


接下来是mysql5.7.30版本的压测,3万个并发打上去,服务器的CPU和磁盘IO都有一定的活动,并未出现完全卡死的情况,说明有一小部分的操作还能够进行下去。但是明显远未达到服务器的最大资源性能。
把连接打到6万,CPU还在活动,但是 磁盘IO几乎停滞了 ,如下图:

这里有个小插曲,并发达到3万2千多的时候,死活就打不上去了。 操作系统的ulimit,实例的innodb_buffer_pool_instances和innodb_open_files都调过了,没有任何作用,只有调整了操作系统的max_map_count,才能够成功突破这个限制,顺利达到6万并发。


mysql8.0.21 

最后是mysql8.0.21版本的压测,6万并发,服务器的CPU和磁盘IO还有一定的活动, 未出现完全卡死的情况

这里还有个小插曲,当并发打到6万5千多并发后,就上不去了,如果强行打上去,会报Not enough resources to complete lock request的错误,应该是哪里设置了65535的限制,以后翻源码瞅瞅。


 
总结
由上面的测试可以发现, mysql随着版本的增加,高并发的性能越来越好 ,其关键就在对原子锁的优化上,这样才能充分利用服务器资源, 在服务器硬件扩展中,获得红利
 
全文完