如何分析 mysqld crash 的原因
某业务系统 mysql crash 了,重启 mysqld 后业务恢复了。业务同事找到我,说需要分析 mysqld crash 的原因。
MySQL 的 err.log 如下:
2022-06-22T12:37:36.675314Z 170605886 [Note] Aborted connection 170605886 to db: '' user: 'fander' host: '192.168.199.1' (Got an error reading communic
ation packets)
12:37:55 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
key_buffer_size=402653184
read_buffer_size=2097152
max_used_connections=6001
max_threads=6000
thread_count=253
connection_count=251
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61913278 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7f6c8a416140
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f74bd2cee70 thread_stack 0x30000
mysqld(my_print_stacktrace+0x3b)[0xf1102b]
mysqld(handle_fatal_signal+0x461)[0x7c3861]
/lib64/libpthread.so.0(+0xf130)[0x7f77081bf130]
mysqld(_Z16digest_add_tokenP16sql_digest_statejP7YYSTYPE+0x81)[0xca9bd1]
mysqld(_ZN16Lex_input_stream16add_digest_tokenEjP7YYSTYPE+0x1d)[0xcb8b5d]
mysqld(_Z8MYSQLlexP7YYSTYPEP7YYLTYPEP3THD+0x130)[0xcbb1a0]
mysqld(_Z10MYSQLparseP3THD+0x9dc)[0xdaf85c]
mysqld(_Z9parse_sqlP3THDP12Parser_stateP19Object_creation_ctx+0x123)[0xce2c73]
mysqld(_Z11mysql_parseP3THDP12Parser_state+0x1cd)[0xce319d]
mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xa7a)[0xce3e7a]
mysqld(_Z10do_commandP3THD+0x19f)[0xce58bf]
mysqld(handle_connection+0x288)[0xda5438]
mysqld(pfs_spawn_thread+0x1b4)[0x12861a4]
/lib64/libpthread.so.0(+0x7df3)[0x7f77081b7df3]
/lib64/libc.so.6(clone+0x6d)[0x7f7706c753dd]
Trying to get some variables.
...
说实话,分析这个东西还真有点难度。
是OOM kill吗?
最常见的 crash 其实是 OOM kill,那么这次是 OOM kill 吗?不是!因为 err.log 里写明了"mysqld got signal 11",而 OOM kill,其实是"signal 9",也就是 kill -9,这种情况 MySQL 会直接挂掉,而没有办法保留堆栈信息的。
是服务器扛不住导致的吗?
从堆栈信息中"connection_count=251" 和 内存使用总值不是,从监控上看也不是,监控数值和历史没有很大的区别。
那就是bug咯?
我认为很有可能,一边让业务回顾最近有没有做过什么变更,crash 之前有没有做过什么特殊操作,我一边去分析 bug 去了。
如何分析bug?
我们先来看看堆栈
我们拿到了崩溃位置 0xca9bd1,如何找到与之相对的代码位置呢?找台测试机,获取对应版本的安装包。我们的版本是 5.7.18,下载两个包,一个是二进制安装包,一个是源码包。
解压二进制安装包后,用 gdb 打开 mysqld,大概方法是
gdb ${解压后的二进制包}/bin/mysqld
在 0xca9bd1 位置打一个断点,大概就会有如下信息:
(gdb)b *0xca9bd1
Breakpoint 1 at 0xca9bd1: file ${源码路径}/sql/sql_digest.cc,line: 379
(gdb)
我们可以看到,gdb 将崩溃位置的文件名和行号都打印出来,剩下的事情,就可以交给开发工程师,按照这个崩溃堆栈来进行问题排查。
以上步骤参考爱可生开源社区的黄炎的专栏《MySQL一问一实验》里的《第25问:MySQL 崩溃了,打印了一些堆栈信息,怎么读?》,有兴趣的直接关注他们公众号看原文,我没必要做文字的搬运工了。
下面我说一下我是怎么做的?
因为我没有源码分析能力,实际上,我并没有用 gdb 定位到具体哪个文件,而我是用 notepad++ 定位的!首先我已经知道了崩溃点在这个位置
mysqld(_Z16digest_add_tokenP16sql_digest_statejP7YYSTYPE+0x81)[0xca9bd1]
用 c++filt 解析就是
[root@fander ~]# c++filt _Z16digest_add_tokenP16sql_digest_statejP7YYSTYPE
digest_add_token(sql_digest_state*, unsigned int, YYSTYPE*)
我们能发现 digest_add_token 是个函数,然后我用 notepad++ 遍历搜索源码文件,如下图:
最后只发现两个源码文件涉及这部分,能定位到具体的行。那么我就"双击"直接跳转到定位的地方。
当然了,我只是从源码能有个大概了解。然后:
2. 我以 "digest_add_token" 为关键字,在 bugs.mysql.com 搜索。
3. 我以 "digest_add_token" 为关键字,在 github 开源官方仓库搜索
这次我找到了,这个 bug 的描述和我在 percona 网站看的描述是一样的。
官方的修复方法比 percona 晚了 5 个月,但修复的方法是一模一样。
实际上是官方不厚道哈。。别人修的 bug,复制粘贴后说自己修复。
从 bug 的编号看,他是一个内部 bug,"Bug#26021187",这种长编号的就是内部发现的 bug,在 bug report 网站是搜索不到的,这也是他的 bug 标题虽然有"digest_add_token"关键字,我也搜索不到的原因。但这里又有个短 bug,我的理解是,有可能有外部有人发现和提交过这个 bug (这也正常,percona 早 5 个月就修复了,所以发现那就是更早的事了。),但官方一直很"狗",如果他们内部也发现了,他们会把外部的 bug 编号关闭,说和内部 bug 编号重复,导致我们外部人无法查到这个 bug。
如图,我以外部 bug 编号 86209 搜索也搜索不到。
看这个报错,Oracle 是把这个外部 bug 关闭和隐藏了。如果 bug 编号不存在应该下面这个报错。
现在我们知道 oracle 修复了这个 bug 了,那么他是哪个版本修复呢?
还是 github 上的那个页面,这里能看到最早在 5.7.21 修复了,然后我们去 release note 里可以再次确认。https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-21.html
Some statements could cause a buffer overflow in the digest code. Thanks to Laurynas Biveinis and Roel van de Paar for the patch. (Bug #26021187)
Bug 是如此描述: 某些语句可能会导致摘要代码中的缓冲区溢出。
MySQL的coredump堆栈信息的采集流程
无论是数据库还是应用程序,当出现问题时,如果能知道异常的堆栈信息,对找到问题根因,从根本上解决,帮助是很大的。
MySQL的堆栈信息,同样能起到辅助解决问题的作用,技术社群的这篇文章《MySQL报障之coredump收集处理流程》给我们介绍了MySQL中采集coredump的流程,可以在实际工作中尝试执行。
1. 配置coredump
core文件是在程序出现异常退出时,保留的异常堆栈文件,能够帮助开发人员快速定位问题,故对于线上的程序,需要开启coredump功能。可以通过配置core-file或者coredumper开启coredump功能。
1.1 core-file
我们需要在my.cnf中的[mysqld]里面加上如下配置。
[mysqld]
core-file
innodb_buffer_pool_in_core_file=OFF
默认情况下,生成的core文件会出现在对应的datadir目录。
启动mysqld_safe之前,操作系统也需要做一些配置:
echo"core.%p.%e.%s" > /proc/sys/kernel/core_pattern
ulimit -c unlimited
sudo sysctl -w fs.suid_dumpable=2
1.2 coredumper
如果没有root权限,无法进行操作系统全局更改时,可以使用如下配置进行配置。
[mysqld]
coredumper
innodb_buffer_pool_in_core_file=OFF
启动mysqld_safe之前,操作系统也需要做一些配置:
ulimit -c unlimited
这样只会影响mysql用户。
core文件会产生在datadir目录。
2. 现场初步分析
2.1 分析error log
首先需要在error log中,搜索backtrace关键字查找异常堆栈。
67912 Build ID: 0eaf4b944b1dbc99a26f9343f301e033bdedeb1d
67913 Server Version: 8.0.25-15-mysqlcluster5.0.7-GA MySQL Cluster, Release GA, Revision b43d2b2e462
67914
67915 Thread pointer: 0x7f914ec27000
67916 Attempting backtrace. You can use the following information to find out
67917 where mysqld died. If you see no messages after this, something went
67918 terribly wrong...
67919 stack_bottom = 7f91608d8c30 thread_stack 0x46000
67920 /mysql/svr/mysql/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x3d) [0x200c33d]
67921 /mysql/svr/mysql/bin/mysqld(handle_fatal_signal+0x37b) [0x1169e4b]
67922 /lib64/libpthread.so.0(+0xf5d0) [0x7f91d95c55d0]
67923 /mysql/svr/mysql/lib/plugin/ha_mysql.so(mysql::ha_mysql::build_order_list_string(String&)+0x6c) [0x7f915951aa4c]
67924 /mysql/svr/mysql/lib/plugin/ha_mysql.so(mysql::ha_greatpart::rnd_init_low(bool)+0x1ac) [0x7f915959765c]
67925 /mysql/svr/mysql/bin/mysqld(handler::ha_rnd_init(bool)+0x22) [0xcc6102]
67926 /mysql/svr/mysql/bin/mysqld(TableScanIterator::Init()+0x4e) [0xeed66e]
67927 /mysql/svr/mysql/bin/mysqld(LimitOffsetIterator::Init()+0x16) [0x122afe6]
67928 /mysql/svr/mysql/bin/mysqld(Query_expression::ExecuteIteratorQuery(THD*)+0x281) [0x10a95a1]
67929 /mysql/svr/mysql/bin/mysqld(Query_expression::execute(THD*)+0x2f) [0x10a994f]
67930 /mysql/svr/mysql/bin/mysqld(Sql_cmd_dml::execute(THD*)+0x516) [0x1029376]
67931 /mysql/svr/mysql/bin/mysqld(mysql_execute_command(THD*, bool)+0x9e0) [0xfcce70]
67932 /mysql/svr/mysql/bin/mysqld(dispatch_sql_command(THD*, Parser_state*, bool)+0x4f1) [0xfd0961]
67933 /mysql/svr/mysql/bin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x1843) [0xfd26b3]
67934 /mysql/svr/mysql/bin/mysqld(do_command(THD*)+0x210) [0xfd3c70]
67935 /mysql/svr/mysql/bin/mysqld() [0x115ac90]
67936 /mysql/svr/mysql/bin/mysqld() [0x24cf38e]
67937 /lib64/libpthread.so.0(+0x7dd5) [0x7f91d95bddd5]
67938 /lib64/libc.so.6(clone+0x6d) [0x7f91d796dead]
67939
67940 Trying to get some variables.
67941 Some pointers may be invalid and cause the dump to abort.
67942 Query (7f913ef65028): select * from `grid-report`.`dp_bi_main_order_acccum` limit 0, 1000
67943 Connection ID (thread ID): 53
67944 Status: NOT_KILLED
可以从这里看到如下几个信息:
2.2 调试core文件
# gdb /mysqld所在目录/mysqld /core文件所在目录/corefile
// 出现gdb命令行,敲入bt命令查看堆栈
(gdb) bt
#0 0x00007f6cd73619d1 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000001169e7d in handle_fatal_signal (sig=11) at /builds/mysql-cluster/myrocks/sql/signal_handler.cc:194
#2
#3 operator() (__ptr=0x7f6c3636c71a, this=0x7f6c0e1b1f2c) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:79
#4 ~unique_ptr (this=0x7f6c0e1b1f2c, __in_chrg=
#5 ~Gdb_execute_plan (this=0x7f6c0e1b1f2c, __in_chrg=
#6 operator() (this=0x7f6c3635c548, __ptr=0x7f6c0e1b1f2c) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:85
#7 operator() (__ptr=0x7f6c0e1b1f2c, this=0x7f6c3635c548) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:79
#8 ~unique_ptr (this=0x7f6c3635c548, __in_chrg=
#9 mysql::execute_direct_query(std::unique_ptr
#10 0x00007f6c0e19b65c in mem_free (this=
#11 ~String (this=
#12 mysql::ha_greatpart::index_read_map_low(unsigned char const*, unsigned long, ha_rkey_function, unsigned int) ()
at /builds/mysql-cluster/myrocks/storage/mysql/ha_greatpart.cc:881
#13 0x0000000000cc6102 in handler::ha_rnd_init (this=0x7f6c720fb028, scan=
#14 0x0000000000eed66e in TableScanIterator::Init (this=0x7f6b7f486c50) at /builds/mysql-cluster/myrocks/sql/row_iterator.h:213
#15 0x000000000122afe6 in LimitOffsetIterator::Init (this=0x7f6b7f486c88)
at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:421
#16 0x00000000010a95a1 in Query_expression::ExecuteIteratorQuery(THD*) ()
at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:421
#17 0x00000000010a994f in Query_expression::execute(THD*) () at /builds/mysql-cluster/myrocks/sql/sql_union.cc:1310
#18 0x0000000001029376 in Sql_cmd_dml::execute(THD*) () at /builds/mysql-cluster/myrocks/sql/sql_select.cc:575
#19 0x0000000000fcce70 in mysql_execute_command(THD*, bool) () at /builds/mysql-cluster/myrocks/sql/sql_parse.cc:4725
#20 0x0000000000fd0961 in dispatch_sql_command (thd=thd@entry=0x7f6beb676000, parser_state=parser_state@entry=0x7f6c3636daa0,
update_userstat=update_userstat@entry=false) at /builds/mysql-cluster/myrocks/sql/sql_parse.cc:5321
#21 0x0000000000fd26b3 in dispatch_command(THD*, COM_DATA const*, enum_server_command) () at /builds/mysql-cluster/myrocks/sql/sql_parse.cc:1969
#22 0x0000000000fd3c70 in do_command (thd=0x7f6beb676000) at /builds/mysql-cluster/myrocks/sql/sql_parse.cc:1417
#23 0x000000000115ac90 in handle_connection (arg=arg@entry=0x7f6bed741340)
at /builds/mysql-cluster/myrocks/sql/conn_handler/connection_handler_per_thread.cc:307
#24 0x00000000024cf38e in pfs_spawn_thread (arg=0x7f6bed4b63e0) at /builds/mysql-cluster/myrocks/storage/perfschema/pfs.cc:2899
#25 0x00007f6cd735cdd5 in start_thread () from /lib64/libpthread.so.0
#26 0x00007f6cd570cead in clone () from /lib64/libc.so.6
此信息需要截图。可以联系研发协助打印一些变量信息。
3. 信息搜集
经过上面的初步分析,需要搜集如下文件提交给研发人员进一步分析。
如果general log很大,需要DBA截取core之前1小时或者10万行的日志即可,可以通过grep、head、tail等命令截取相关日志。
Mysql 性能优化
#数据结构优化
良好的逻辑设计和物理设计是高性能的基石。
#数据类型优化
#数据类型优化基本原则
#类型的选择
#表设计
应该避免的设计问题:
#范式和反范式
范式化目标是尽量减少冗余,而反范式化则相反。
范式化的优点:
范式化的缺点:
在真实世界中,很少会极端地使用范式化或反范式化。实际上,应该权衡范式和反范式的利弊,混合使用。
#索引优化
索引优化应该是查询性能优化的最有效手段。
如果想详细了解索引特性请参考:Mysql 索引(opens new window)
#何时使用索引
#索引优化策略
#SQL 优化
使用EXPLAIN命令查看当前 SQL 是否使用了索引,优化后,再通过执行计划(EXPLAIN)来查看优化效果。
SQL 优化基本思路:
#优化COUNT()查询
COUNT()有两种作用:
统计列值时,要求列值是非空的,它不会统计 NULL。如果确认括号中的表达式不可能为空时,实际上就是在统计行数。最简单的就是当使用COUNT(*)时,并不是我们所想象的那样扩展成所有的列,实际上,它会忽略所有的列而直接统计行数。
我们最常见的误解也就在这儿,在括号内指定了一列却希望统计结果是行数,而且还常常误以为前者的性能会更好。但实际并非这样,如果要统计行数,直接使用COUNT(*),意义清晰,且性能更好。
(1)简单优化
SELECT count(*) FROM world.city WHERE id > 5;
SELECT (SELECT count(*) FROM world.city) - count(*)
FROM world.city WHERE id <= 5;
(2)使用近似值
有时候某些业务场景并不需要完全精确的统计值,可以用近似值来代替,EXPLAIN出来的行数就是一个不错的近似值,而且执行EXPLAIN并不需要真正地去执行查询,所以成本非常低。通常来说,执行COUNT()都需要扫描大量的行才能获取到精确的数据,因此很难优化,MySQL 层面还能做得也就只有覆盖索引了。如果不还能解决问题,只有从架构层面解决了,比如添加汇总表,或者使用 Redis 这样的外部缓存系统。
#优化关联查询
在大数据场景下,表与表之间通过一个冗余字段来关联,要比直接使用JOIN有更好的性能。
如果确实需要使用关联查询的情况下,需要特别注意的是:
要理解优化关联查询的第一个技巧,就需要理解 MySQL 是如何执行关联查询的。当前 MySQL 关联执行的策略非常简单,它对任何的关联都执行嵌套循环关联操作,即先在一个表中循环取出单条数据,然后在嵌套循环到下一个表中寻找匹配的行,依次下去,直到找到所有表中匹配的行为为止。然后根据各个表匹配的行,返回查询中需要的各个列。
太抽象了?以上面的示例来说明,比如有这样的一个查询:
SELECT A.xx,B.yy
FROM A INNER JOIN B USING(c)
WHERE A.xx IN (5,6)
假设 MySQL 按照查询中的关联顺序 A、B 来进行关联操作,那么可以用下面的伪代码表示 MySQL 如何完成这个查询:
outer_iterator = SELECT A.xx,A.c FROM A WHERE A.xx IN (5,6);
outer_row = outer_iterator.next;
while(outer_row) {
inner_iterator = SELECT B.yy FROM B WHERE B.c = outer_row.c;
inner_row = inner_iterator.next;
while(inner_row) {
output[inner_row.yy,outer_row.xx];
inner_row = inner_iterator.next;
}
outer_row = outer_iterator.next;
}
可以看到,最外层的查询是根据A.xx列来查询的,A.c上如果有索引的话,整个关联查询也不会使用。再看内层的查询,很明显B.c上如果有索引的话,能够加速查询,因此只需要在关联顺序中的第二张表的相应列上创建索引即可。
#优化GROUP BY和DISTINCT
Mysql 优化器会在内部处理的时候相互转化这两类查询。它们都可以使用索引来优化,这也是最有效的优化方法。
#优化LIMIT
当需要分页操作时,通常会使用LIMIT加上偏移量的办法实现,同时加上合适的ORDER BY字句。如果有对应的索引,通常效率会不错,否则,MySQL 需要做大量的文件排序操作。
一个常见的问题是当偏移量非常大的时候,比如:LIMIT 10000 20这样的查询,MySQL 需要查询 10020 条记录然后只返回 20 条记录,前面的 10000 条都将被抛弃,这样的代价非常高。
优化这种查询一个最简单的办法就是尽可能的使用覆盖索引扫描,而不是查询所有的列。然后根据需要做一次关联查询再返回所有的列。对于偏移量很大时,这样做的效率会提升非常大。考虑下面的查询:
SELECT film_id,description FROM film ORDER BY title LIMIT 50,5;
如果这张表非常大,那么这个查询最好改成下面的样子:
SELECT film.film_id,film.description
FROM film INNER JOIN (
SELECT film_id FROM film ORDER BY title LIMIT 50,5
) AS tmp USING(film_id);
这里的延迟关联将大大提升查询效率,让 MySQL 扫描尽可能少的页面,获取需要访问的记录后在根据关联列回原表查询所需要的列。
有时候如果可以使用书签记录上次取数据的位置,那么下次就可以直接从该书签记录的位置开始扫描,这样就可以避免使用OFFSET,比如下面的查询:
SELECT id FROM t LIMIT 10000, 10;
改为:
SELECT id FROM t WHERE id > 10000 LIMIT 10;
其他优化的办法还包括使用预先计算的汇总表,或者关联到一个冗余表,冗余表中只包含主键列和需要做排序的列。
#优化 UNION
MySQL 总是通过创建并填充临时表的方式来执行UNION查询。因此很多优化策略在UNION查询中都没有办法很好的时候。经常需要手动将WHERE、LIMIT、ORDER BY等字句“下推”到各个子查询中,以便优化器可以充分利用这些条件先优化。
除非确实需要服务器去重,否则就一定要使用UNION ALL,如果没有ALL关键字,MySQL 会给临时表加上DISTINCT选项,这会导致整个临时表的数据做唯一性检查,这样做的代价非常高。当然即使使用 ALL 关键字,MySQL 总是将结果放入临时表,然后再读出,再返回给客户端。虽然很多时候没有这个必要,比如有时候可以直接把每个子查询的结果返回给客户端。
#优化查询方式
#切分大查询
一个大查询如果一次性执行的话,可能一次锁住很多数据、占满整个事务日志、耗尽系统资源、阻塞很多小的但重要的查询。
DELEFT FROM messages WHERE create < DATE_SUB(NOW(), INTERVAL 3 MONTH);
rows_affected = 0
do {
rows_affected = do_query(
"DELETE FROM messages WHERE create < DATE_SUB(NOW(), INTERVAL 3 MONTH) LIMIT 10000")
} while rows_affected > 0
#分解大连接查询
将一个大连接查询(JOIN)分解成对每一个表进行一次单表查询,然后将结果在应用程序中进行关联,这样做的好处有:
SELECT * FROM tag
JOIN tag_post ON tag_post.tag_id=tag.id
JOIN post ON tag_post.post_id=post.id
WHERE tag.tag='mysql';
SELECT * FROM tag WHERE tag='mysql';
SELECT * FROM tag_post WHERE tag_id=1234;
SELECT * FROM post WHERE post.id IN (123,456,567,9098,8904);
#执行计划(EXPLAIN)
如何判断当前 SQL 是否使用了索引?如何检验修改后的 SQL 确实有优化效果?
在 SQL 中,可以通过执行计划(EXPLAIN)分析SELECT查询效率。
mysql> explain select * from user_info where id = 2\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: user_info
partitions: NULL
type: const
possible_keys: PRIMARY
key: PRIMARY
key_len: 8
ref: const
rows: 1
filtered: 100.00
Extra: NULL
1 row in set, 1 warning (0.00 sec)
EXPLAIN参数说明:
更多内容请参考:MySQL 性能优化神器 Explain 使用分析(opens new window)
#optimizer trace
在 MySQL 5.6 及之后的版本中,我们可以使用 optimizer trace 功能查看优化器生成执行计划的整个过程。有了这个功能,我们不仅可以了解优化器的选择过程,更可以了解每一个执行环节的成本,然后依靠这些信息进一步优化查询。
如下代码所示,打开 optimizer_trace 后,再执行 SQL 就可以查询 information_schema.OPTIMIZER_TRACE 表查看执行计划了,最后可以关闭 optimizer_trace 功能:
SET optimizer_trace="enabled=on";
SELECT * FROM person WHERE NAME >'name84059' AND create_time>'2020-01-24 05:00
SELECT * FROM information_schema.OPTIMIZER_TRACE;
SET optimizer_trace="enabled=off";
#数据模型和业务