马上注册,结交更多数据大咖,获取更多知识干货,轻松玩转大数据
您需要 登录 才可以下载或查看,没有帐号?立即注册
x
前 言经过周末两天的折腾,在大家的帮助下最终将用户 DB 的性能峰值由最初的不到 8W 的 QPS + TPS 提升至 17W,心情也由最初的忐忑过渡到现在的平静,现在想来,整个的优化过程感觉还是比较好玩的,趁着现在还有些印象,就把整个排查 & 优化过程详细的记录下来,以备不时之需,也希望能给人一些启发来解决其它问题,同时,也让俺感谢一下在整个解决过程中给予很多帮助的同事,没有你们在背后的帮助,DB 端解决问题的时间要更久! 问题背景上周团队聚餐的时候,老大说有一个用户使用 DB 的时候遇到了问题,现有的 DB 性能无法满足用户的性能需求。用户在对现有的 DB 进行压力测试时发现 QPS + TPS 小于 7W/S,继续加大压力的时候 Load 上涨、Idle CPU 很低、Thread running 飙升、性能下降,最终导致网站处理并发能力的下降,无法达到预期的吞吐量。用户在对现有逻辑及吞吐量计算的基础上提出了性能指标,即 DB 的单机性能 QPS + TPS 大于 10W/S, 只有这样才能满足业务要求,否则 DB 就是整个链路的瓶颈。由于用户的上线时间临近,上线压力比较大,老大说周末尽力搞定,如果搞不定,只能上最好的机器来解决性能问题,这样的话,成本就要上来了。(当时正在吃饭,瞬间感觉压力山大,不能好好的吃肉了……,有木有……!) 现场信息收集第二天还没醒就收到老大的消息,然后怀着疑惑的心情火速上线,登录到机器上,开始了 DB 性能的调优之旅…… 首先,使用 orzdba 监控工具查看了用户实例的性能状态,如下所示: [AppleScript] 纯文本查看 复制代码 -----load-avg---- ---cpu-usage--- ---------QPS---------------TPS------Hit%-----------threads------
1m 5m 15m |usr sys idl iow| ins upd del sel iud| lor hit| run con cre cac|
99.86 46.70 18.68| 65 25 10 0| 1045 3411 0 62800 4456| 304288 100.00| 251 963 0 0|
99.86 46.70 18.68| 64 25 11 0| 1005 2956 0 64017 2961| 311912 100.00| 299 963 0 0|
99.86 46.70 18.68| 66 25 9 0| 1223 3274 0 64511 4497| 309941 100.00| 325 963 0 0|
99.86 46.70 18.68| 66 24 10 0| 1188 2992 0 64425 4180| 413496 100.00| 331 963 0 0|
97.86 46.70 18.68| 66 24 10 0| 1148 3319 0 63536 4467| 307956 100.00| 262 963 0 0|
97.86 46.70 18.68| 63 25 11 0| 1162 3723 0 64628 4485| 300747 100.00| 306 963 0 0|
97.86 46.70 18.68| 66 25 9 0| 1117 4416 0 64077 5533| 305845 100.00| 273 963 0 0|
96.86 46.70 18.68| 64 24 12 0| 1101 4240 0 63520 5341| 307361 100.00| 234 963 0 0|
96.86 46.70 18.68| 65 25 10 0| 1128 4502 0 62604 5630| 312940 100.00| 52 963 0 0|
96.86 46.92 18.68| 65 25 10 0| 900 4846 0 60648 5746| 298142 100.00| 282 963 0 0|
从上面的性能信息可以发现命中率 100%, 即用户基本是全内存操作,thread running 较高,CPU 有少量, thread running 彪升,到底线程在做什么呢?怀着这样的疑问,然后执行了一下 pstack {pid of mysqld} > pid.info 以获取实例的内部线程信息,然后使用 pt-pmp pid.info 将堆栈信息进行显示,发现了如下的信息: [AppleScript] 纯文本查看 复制代码 192 __lll_lock_wait(libpthread.so.0),_L_lock_974(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),inline_mysql_mutex_lock(mysql_thread.h:690),lock(mysql_thread.h:690),open_table(mysql_thread.h:690),open_and_process_table(sql_base.cc:4726),open_tables(sql_base.cc:4726),open_normal_and_derived_tables(sql_base.cc:5856),execute_sqlcom_select(sql_parse.cc:5129),mysql_execute_command(sql_parse.cc:2656),mysql_parse(sql_parse.cc:6408),dispatch_command(sql_parse.cc:1340),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
31 __lll_lock_wait(libpthread.so.0),_L_lock_790(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),rw_pr_wrlock(thr_rwlock.c:397),inline_mysql_prlock_wrlock(mysql_thread.h:984),MDL_map_partition::move_from_hash_to_lock_mutex(mysql_thread.h:984),find_or_insert(mdl.cc:898),MDL_map::find_or_insert(mdl.cc:898),try_acquire_lock_impl(mdl.cc:2033),MDL_context::acquire_lock(mdl.cc:2033),open_table_get_mdl_lock(sql_base.cc:2587),open_table(sql_base.cc:2587),open_and_process_table(sql_base.cc:4726),open_tables(sql_base.cc:4726),open_normal_and_derived_tables(sql_base.cc:5856),execute_sqlcom_select(sql_parse.cc:5129),mysql_execute_command(sql_parse.cc:2656),mysql_parse(sql_parse.cc:6408),dispatch_command(sql_parse.cc:1340),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
...
...
1 lfind(libc.so.6),lsearch(lf_hash.c:267),lf_hash_search(lf_hash.c:267),find_or_create_digest(pfs_digest.cc:223),end_statement_v1(pfs.cc:4815),inline_mysql_end_statement(mysql_statement.h:215),dispatch_command(mysql_statement.h:215),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
根据上述的 pt-pmp & pstack 文件相结合,可以看到如下堆栈: [AppleScript] 纯文本查看 复制代码 #0 0x00007fc5f03eef7d in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007fc5f03ead77 in _L_lock_974 () from /lib64/libpthread.so.0
#2 0x00007fc5f03ead20 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x00000000006a64e8 in inline_mysql_mutex_lock (src_line=115, src_file=0xc73308 "../sql/table_cache.h", that=0x138d9e0 <table_cache_manager>) at ../include/mysql/psi/mysql_thread.h:690
#4 lock (this=0x138d9e0 <table_cache_manager>) at ../sql/table_cache.h:115
#5 open_table (thd=thd@entry=0x397e5210, table_list=table_list@entry=0x7fbd44004e20, ot_ctx=ot_ctx@entry=0x7fbd740876e0) at ../sql/sql_base.cc:2944
#6 0x00000000006aed49 in open_and_process_table (ot_ctx=0x7fbd740876e0, has_prelocking_list=false, prelocking_strategy=0x7fbd74087920, flags=0, counter=0x397e7050, tables=0x7fbd44004e20, lex=0x397e6fa0, thd=0x397e5210) at ../sql/sql_base.cc:4726
#7 open_tables (thd=thd@entry=0x397e5210, start=start@entry=0x7fbd74087918, counter=0x397e7050, flags=flags@entry=0, prelocking_strategy=prelocking_strategy@entry=0x7fbd74087920) at ../sql/sql_base.cc:5159
#8 0x00000000006af7fa in open_normal_and_derived_tables (thd=thd@entry=0x397e5210, tables=0x7fbd44004e20, flags=flags@entry=0) at ../sql/sql_base.cc:5856
#9 0x0000000000572a48 in execute_sqlcom_select (thd=thd@entry=0x397e5210, all_tables=<optimized out>) at ../sql/sql_parse.cc:5129
#10 0x00000000006fa010 in mysql_execute_command (thd=thd@entry=0x397e5210) at ../sql/sql_parse.cc:2656
根据上面收集的信息我们可以清楚的得出以下结论: - 应用在执行SQL语句的过程中,table_cache_manager 中的锁冲突比较严重;
- MySQL Server 层中的 MDL_lock 冲突比较重;
- 实例开启了 Performance_schema 功能;
经过了上面的分析,我们需要着重查看上述问题的相关变量,变量设置的情况会对性能造成直接的影响,执行结果如下: [AppleScript] 纯文本查看 复制代码 MySQL [(none)]> show variables like '%performance_schema';
+--------------------+-------+
| Variable_name | Value |
+--------------------+-------+
| performance_schema | ON |
+--------------------+-------+
1 row in set (0.00 sec)
MySQL [(none)]> show variables like '%instances';
+-----------------------------------------+--------+
| Variable_name | Value |
+-----------------------------------------+--------+
| innodb_buffer_pool_instances | 8 |
| metadata_locks_hash_instances | 8 |
| ........................................|........|
| ........................................|........|
| table_open_cache_instances | 1 |
+-----------------------------------------+--------+
10 rows in set (0.00 sec)
参数分析
这里我们先来介绍一下上述参数在 MySQL 中的作用 & 含义: - table_open_cache_instances 简介
table_open_cache_instances 指的是 MySQL 缓存 table 句柄的分区的个数,而每一个 cache_instance 可以包含不超过 table_open_cache/table_open_cache_instances 的table_cache_element,详细可以参考官方的说明文档:table_open_cache_instances,MySQL 打开表的过程可以简单的概括为: 1、根据线程的 thread_id 确定线程将要使用的 table_cache,即 thread_id % table_cache_instances;
2、从该 tabel_cache 元素中查找相关系连的 table_cache_element,如果存在转 3,如果不存在转 4;
3、从 2 中查找的table_cache_element 的 free_tables 中出取一个并返回,并调整 table_cache_element 中的 free_tables & used_tables 元素;
4、如果 2 中不存在,则重新创建一个 table, 并加入对应的 table_cache_element 的 used_tables的列表; 从以上过程可以看出,MySQL 在打开表的过程中会首先从 table_cache 中进行查找有没有可以直接使用的表句柄,有则直接使用,没有则会创建并加入到对应的 table_cache 中对应的 table_cache_element 中,从刚才提取的现场信息来看,有大量的线程在查找 table_cache 的过程中阻塞着了,而 table_open_cache_instances 的个数为 1, 因此,此参数的设置需要调整,由于 table_open_cache_instances 的大小和 线程 ID & 并发 有关系,考虑当前的并发是1000左右,于是将该植设置为 32; MySQL 中不同的线程虽然使用各自的 table 句柄,但是共享着同一个table_share,如果想从源码上了解 table & table_share 以及 两者之间的相互,可以从变量 table_open_cache, table_open_cache_instances,table_definition_cache 入手,阅读 Table_cache_manager, Table_cache, Table_cache::get_table 等相关代码,由于篇幅限制,在此不在详述。 在 5.1 中有一个 binlog log 乱序的问题,详情及复现方法可以参考这篇文章:alter table rename 操作导致复制中断,MDL_LOCK 就是为了解决上述问题而在 5.5 中引入的。简单的说 MDL Lock 是 MySQL Server 层中的表锁,主要是为了控制 Server 层 DDL & DML 的并发而设计的, 但是 5.5 的设计中只有一把大锁,所以到5.6中添加了参数 metadata_locks_hash_instances 来控制分区的数量,进而实现大锁的拆分,虽然锁的拆分提高了并发的性能,但是仍然存在着不少的性能问题,所以在 5.7.4 中 MDL Lock 的实现方式采用了 lock free 算法,彻底的解决了 Server 层表锁的性能问题,而参数 metadata_locks_hash_instances 也将会在之后的某个版本中被删除掉;
由于实例中的表的数目比较多,而 metadata_locks_hash_instances 的参数设置仅为8,因此,为了将底锁的冲突的可能性,我们将此值设置为 32; - Performance Schema 作用 & 影响
通俗的说,performance schema 是 MySQL 的内部诊断器,用于记录 MySQL 在运行期间的各种信息,如表锁情况、mutex 竟争情况、执行语句的情况等,和 Information Schema 类似的是拥用的信息都是内存信息,而不是存在磁盘上的,但和 information_schema 有以下不同点: - information_schema 中的信息都是从 MySQL 的内存对象中读出来的,只有在需要的时候才会读取这些信息,如 processlist, profile, innodb_trx 等,不需要额外的存储或者函数调用,而 performance schema 则是通过一系列的回调函数来将这些信息额外的存储起来,使用的时候进行显示,因此 performance schema 消耗更多的 CPU & memory 资源;
- Information_schema 中的表是没有表定义文件的,表结构是在内存中写死的,而 performation_schema 中的表是有表定义文件的;
- 实现方式不同,Information_schema 只是对内存的 traverse copy, 而 performance_schema 则使用固定的接口来进行实现;
- 作用不同,Information_schema 主要是轻量级的使用,即使在使用的时候也很少会有性能影响,performance_schema 则是 MySQL 的内部监控系统,可以很好的定位性能问题,但也很影响性能;
由以上的分析不难看出,在性能要求比较高的情况下,关闭 performance_schema 是一个不错的选择,因此将 performance_schema 关闭。另外关闭 performance_schema 的一个原因则是因为它本身的稳定性,因为之前在使用 performance_schema 的过程中遇到了不稳定的问题,当然,遇到一个问题我们就会修复一个,只是考虑到性能问题,我们暂时将其关闭。 Performance_schema 的详细使用说明可以参考:
经过上面的分析和判断,我们对参数做了如下的调整: [AppleScript] 纯文本查看 复制代码 table_open_cache_instances=32
metadata_locks_hash_instances=32
performance_schema=OFF
innodb_purge_threads=4
勉强解决问题
调整了以上参数后,我们重启实例,然后要求客户做新一轮的压力测试,测试部分数据如下: [AppleScript] 纯文本查看 复制代码 -----load-avg---- ---cpu-usage--- ---------QPS---------------TPS------Hit%-----------threads------
1m 5m 15m |usr sys idl iow| ins upd del sel iud| lor hit| run con cre cac|
9.91 2.75 3.16| 24 14 62 0| 0 3698 0 87124 3698| 304288 100.00| 23 963 0 0|
9.91 2.75 3.16| 41 24 35 0| 0 7191 0 124506 7191| 311912 100.00| 20 963 0 0|
12.48 3.41 3.37| 45 24 31 0| 352 8547 0 122248 8899| 309941 100.00| 35 963 0 0|
12.48 3.41 3.37| 55 27 18 0| 1514 7338 0 118130 8852| 413496 100.00| 217 963 0 0|
12.48 3.41 3.49| 60 27 13 0| 1815 6778 0 108114 8593| 307956 100.00| 20 963 0 0|
12.48 3.41 3.49| 58 25 17 0| 1909 7575 0 102566 9484| 300747 100.00| 17 963 0 0|
12.48 3.78 3.49| 57 23 20 0| 2022 7893 0 101197 9915| 305845 100.00| 21 963 0 0|
13.86 3.78 3.68| 58 26 16 0| 1732 7498 0 104869 9230| 307361 100.00| 27 963 0 0|
13.86 4.38 3.68| 57 24 19 0| 2067 6093 0 106261 8160| 312940 100.00| 33 963 0 0|
15.86 4.38 3.68| 57 24 19 0| 2008 5661 0 102623 7669| 298142 100.00| 12 963 0 0|
从以上的测试数据来看, QPS + TPS > 10W 已经满足要求,通过 perf top -p {pidof mysqld} 命令查看了一下系统负载,发现了一处比较吃 CPU 的地方 ut_delay,详情如下: [AppleScript] 纯文本查看 复制代码 20.69% mysqld [.] ut_delay(unsigned long)
4.86% mysqld [.] my_hash_sort_utf8
3.94% mysqld [.] mutex_spin_wait(ib_mutex_t*, char const*, unsigned long)
3.59% mysqld [.] read_view_open_now_low(unsigned long, mem_block_info_t*)
3.13% [kernel] [k] _raw_spin_lock
3.05% mysqld [.] my_ismbchar_utf8
2.77% mysqld [.] my_charpos_mb
2.29% mysqld [.] my_strnxfrm_unicode
1.80% mysqld [.] MYSQLparse(THD*)
1.61% libc-2.17.so [.] __memcpy_ssse3_back
1.58% libpthread-2.17.so [.] pthread_mutex_lock
0.73% mysqld [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
0.73% mysqld [.] my_convert
0.71% libc-2.17.so [.] _int_malloc
使用 perf record & perf report 进行分析,发现调用比较多的地方是: mutex_spin_wait,于是断定 Innodb 底层资源冲突比较严重,根据以往的经验执行如下命令: [AppleScript] 纯文本查看 复制代码 mysql> show variables like '%spin%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| innodb_spin_wait_delay | 10000 |
| innodb_sync_spin_loops | 30 |
+------------------------+-------+
2 rows in set (5.55 sec)
在 MySQL 内部,当 innodb 线程获取 mutex 资源而得不到满足时,会最多进行 innodb_sync_spin_loops 次尝试获取 mutex 资源,每次失败后会调用 ut_delay(ut_rnd_interval(0, srv_spin_wait_delay),导致 ut_delay 占用了过多的 CPU, 其中 ut_delay 的定义如下: [AppleScript] 纯文本查看 复制代码 /*************************************************************//**
Runs an idle loop on CPU. The argument gives the desired delay
in microseconds on 100 MHz Pentium + Visual C++.
@return dummy value */
UNIV_INTERN
ulint
ut_delay(
/*=====*/
ulint delay) /*!< in: delay in microseconds on 100 MHz Pentium */
{
ulint i, j;
j = 0;
for (i = 0; i < delay * 50; i++) {
j += i;
UT_RELAX_CPU();
}
if (ut_always_false) {
ut_always_false = (ibool) j;
}
return(j);
}
由于这两个值的设定取决于实例的负载以及资源的竟争情况,所以不断的尝试设置这两个参数的值,经过多次的尝试最终将这两个参数分别设置为:innodb_spin_wait_delay = 6, innodb_sync_spin_loops = 20 (请注意这两个值不是推荐值!!!) 才将 ut_delay 的占用资源降下来,最终降低了不必要的 CPU 消耗的同时 idle cpu 也稳定在了 20+,具体资源占用详情如下: [AppleScript] 纯文本查看 复制代码 6.52% mysqld [.] my_hash_sort_utf8
3.93% [kernel] [k] _raw_spin_lock
3.82% mysqld [.] my_ismbchar_utf8
3.65% mysqld [.] my_charpos_mb
3.31% mysqld [.] my_strnxfrm_unicode
3.09% mysqld [.] ut_delay(unsigned long)
2.58% mysqld [.] read_view_open_now_low(unsigned long, mem_block_info_t*)
2.38% mysqld [.] MYSQLparse(THD*)
1.91% libc-2.17.so [.] __memcpy_ssse3_back
1.89% mysqld [.] mutex_spin_wait(ib_mutex_t*, char const*, unsigned long)
1.79% libpthread-2.17.so [.] pthread_mutex_lock
优化到这个地步似乎达到了客户要求的性能,即 DB 单机性能为 QPS + TPS > 10W,可是如果并发量在加大,我们的 DB 能扛住更高的压力吗? 又起波澜经过上面参数的调整,DB 已经不是性能的瓶颈,应用的吞吐量由之前的 1100 -> 1400+,但是离 2000 的吞吐量还比较远,瓶颈出现在了应用端,为了增加吞吐量,客户又增加了几台客户端机器,连接数也由之前的 900+ 上升到 1000+,此时发现 DB 虽然能够响应,但偶尔会出现 thread running 飙高的情况,具体运行状态如下,其中 mysql_com_tps = (mysql_com_insert + mysql_com_update + mysql_com_delete): [AppleScript] 纯文本查看 复制代码 +---------------------+--------+---------+------------------+------------------+------------------+------------------+---------------+-----------------+---------------------+
| dtime | load_1 | idlecpu | mysql_com_insert | mysql_com_update | mysql_com_delete | mysql_com_select | mysql_com_tps | threads_running | threads_connections |
+---------------------+--------+---------+------------------+------------------+------------------+------------------+---------------+-----------------+---------------------+
| 2016-07-03 21:48:24 | 5.78 | 30.00 | 1706 | 6573 | 0 | 97359 | 8279 | 25 | 1011 |
| 2016-07-03 21:48:25 | 5.78 | 41.00 | 1606 | 7018 | 0 | 98273 | 8624 | 17 | 1011 |
| 2016-07-03 21:48:26 | 5.78 | 33.00 | 1616 | 5739 | 0 | 93752 | 7355 | 108 | 1011 |
| 2016-07-03 21:48:27 | 5.78 | 39.00 | 1505 | 6436 | 0 | 91381 | 7941 | 12 | 1011 |
| 2016-07-03 21:48:28 | 8.20 | 36.00 | 1849 | 4514 | 0 | 87881 | 6363 | 156 | 1011 |
| 2016-07-03 21:48:29 | 8.20 | 28.00 | 1702 | 6386 | 0 | 97621 | 8088 | 35 | 1011 |
| 2016-07-03 21:48:30 | 8.20 | 42.00 | 1442 | 6708 | 0 | 94920 | 8150 | 24 | 1011 |
| 2016-07-03 21:48:31 | 8.20 | 28.00 | 1399 | 8283 | 0 | 98801 | 9682 | 189 | 1011 |
| 2016-07-03 21:48:32 | 8.20 | 28.00 | 1254 | 7960 | 0 | 90461 | 9214 | 137 | 1011 |
| 2016-07-03 21:48:33 | 9.86 | 23.00 | 1039 | 7557 | 0 | 92145 | 8596 | 193 | 1011 |
| 2016-07-03 21:48:34 | 9.86 | 36.00 | 1358 | 7696 | 0 | 85274 | 9054 | 301 | 1011 |
| 2016-07-03 21:48:35 | 9.86 | 39.00 | 1069 | 8148 | 0 | 80185 | 9217 | 346 | 1011 |
| 2016-07-03 21:48:36 | 9.86 | 44.00 | 1019 | 8484 | 0 | 77787 | 9503 | 378 | 1011 |
| 2016-07-03 21:48:37 | 9.86 | 41.00 | 1023 | 7290 | 0 | 74965 | 8313 | 341 | 1011 |
| 2016-07-03 21:48:38 | 10.36 | 39.00 | 987 | 8031 | 0 | 83857 | 9018 | 279 | 1011 |
| 2016-07-03 21:48:39 | 10.36 | 39.00 | 1108 | 7165 | 0 | 84070 | 8273 | 255 | 1011 |
| 2016-07-03 21:48:40 | 10.36 | 42.00 | 1219 | 5804 | 0 | 80959 | 7023 | 22 | 1011 |
| 2016-07-03 21:48:41 | 10.36 | 40.00 | 1034 | 6546 | 0 | 82380 | 7580 | 296 | 1011 |
| 2016-07-03 21:48:42 | 10.36 | 41.00 | 809 | 5973 | 0 | 79554 | 6782 | 319 | 1011 |
| 2016-07-03 21:48:43 | 10.65 | 39.00 | 949 | 7252 | 0 | 79690 | 8201 | 312 | 1011 |
查找问题原因
Thread running 的偶尔飙升引起了我的注意,说明内部必然有冲突,随着压力和并发量的不断增大,应用可能会受到类似之前的影响,因此很有必要查看其中的原因并尽最大的努力解决之。通过仔细的观察 thread running & mysql com 信息,当 thread running 较高 & com 信息较低的时候,执行了 pt-pmp -p {pid of mysqld},抓到了以下信息: [AppleScript] 纯文本查看 复制代码 Wed Jul 6 14:21:22 CST 2016
179 pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:214),sync_array_wait_event(sync0arr.cc:424),mutex_spin_wait(sync0sync.cc:580),mutex_enter_func(sync0sync.ic:218),pfs_mutex_enter_func(sync0sync.ic:218),read_view_remove(sync0sync.ic:218),read_view_close_for_mysql(sync0sync.ic:218),ha_innobase::external_lock(ha_innodb.cc:12326),handler::ha_external_lock(handler.cc:7190),unlock_external(lock.cc:646),mysql_unlock_tables(lock.cc:389),mysql_unlock_some_tables(lock.cc:389),JOIN::optimize(sql_optimizer.cc:406),mysql_execute_select(sql_select.cc:1087),mysql_select(sql_select.cc:1087),handle_select(sql_select.cc:110),execute_sqlcom_select(sql_parse.cc:5156),mysql_execute_command(sql_parse.cc:2656),mysql_parse(sql_parse.cc:6408),dispatch_command(sql_parse.cc:1340),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
150 pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:214),sync_array_wait_event(sync0arr.cc:424),mutex_spin_wait(sync0sync.cc:580),mutex_enter_func(sync0sync.ic:218),pfs_mutex_enter_func(sync0sync.ic:218),read_view_open_now(sync0sync.ic:218),trx_assign_read_view(trx0trx.cc:1481),row_search_for_mysql(row0sel.cc:4090),ha_innobase::index_read(ha_innodb.cc:7516),handler::index_read_idx_map(handler.cc:6846),handler::ha_index_read_idx_map(handler.cc:2787),join_read_(handler.cc:2787),join_read__table(handler.cc:2787),make_join_statistics(sql_optimizer.cc:3592),JOIN::optimize(sql_optimizer.cc:363),mysql_execute_select(sql_select.cc:1087),mysql_select(sql_select.cc:1087),handle_select(sql_select.cc:110),execute_sqlcom_select(sql_parse.cc:5156),mysql_execute_command(sql_parse.cc:2656),mysql_parse(sql_parse.cc:6408),dispatch_command(sql_parse.cc:1340),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
7 __lll_lock_wait(libpthread.so.0),_L_cond_lock_973(libpthread.so.0),__pthread_mutex_cond_lock(libpthread.so.0),pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:214),sync_array_wait_event(sync0arr.cc:424),mutex_spin_wait(sync0sync.cc:580),mutex_enter_func(sync0sync.ic:218),pfs_mutex_enter_func(sync0sync.ic:218),read_view_open_now(sync0sync.ic:218),trx_assign_read_view(trx0trx.cc:1481),row_search_for_mysql(row0sel.cc:4090),ha_innobase::index_read(ha_innodb.cc:7516),handler::index_read_idx_map(handler.cc:6846),handler::ha_index_read_idx_map(handler.cc:2787),join_read_(handler.cc:2787),join_read__table(handler.cc:2787),make_join_statistics(sql_optimizer.cc:3592),JOIN::optimize(sql_optimizer.cc:363),mysql_execute_select(sql_select.cc:1087),mysql_select(sql_select.cc:1087),handle_select(sql_select.cc:110),execute_sqlcom_select(sql_parse.cc:5156),mysql_execute_command(sql_parse.cc:2656),mysql_parse(sql_parse.cc:6408),dispatch_command(sql_parse.cc:1340),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
1 operator(read0read.cc:296),ut_list_map<ut_list_base<trx_t>,(read0read.cc:296),read_view_open_now_low(read0read.cc:296),read_view_open_now(read0read.cc:388),trx_assign_read_view(trx0trx.cc:1481),row_search_for_mysql(row0sel.cc:4090),ha_innobase::index_read(ha_innodb.cc:7516),handler::index_read_idx_map(handler.cc:6846),handler::ha_index_read_idx_map(handler.cc:2787),join_read_(handler.cc:2787),join_read__table(handler.cc:2787),make_join_statistics(sql_optimizer.cc:3592),JOIN::optimize(sql_optimizer.cc:363),mysql_execute_select(sql_select.cc:1087),mysql_select(sql_select.cc:1087),handle_select(sql_select.cc:110),execute_sqlcom_select(sql_parse.cc:5156),mysql_execute_command(sql_parse.cc:2656),mysql_parse(sql_parse.cc:6408),dispatch_command(sql_parse.cc:1340),do_command(sql_parse.cc:1037),do_handle_one_connection(sql_connect.cc:990),handle_one_connection(sql_connect.cc:906),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
...
...
从上面的现场信息不难看出有很大一部分线程是在执行 read_view 的相关操作中被阻塞着了,那么什么是 read view,它的作用是什么,为什么会有大量的线程执行这个操作的时候被阻塞呢? 什么是 read viewread view 又称读视图,用于存储事务创建时的活跃事务集合。当事务创建时,线程会对 trx_sys 上全局锁,然后遍历当前活跃事务列表,将当前活跃事务的ID存储在数组中的同时,记录最大事务 low_limit_id & 最小事务 high_limit_id & 最小序列化事务 low_limit_no。 read view 的作用是什么Innodb record 格式包含 {记录头,主建,Trx_id,roll_ptr, extra_column} 等信息。 当事务执行时,凡是大于low_limit_id 的数据对于事务是不可见的,凡是事务小于 high_limit_id 的数据都是可见的,事务 ID 是 read_view 数组中的某一个时也是不可见的,Purge thread 在执行 Purge 操作时,凡是小于 low_limit_no 的数据,都是可以被 Purge 的,因此, read view 是 MySQL MVCC 实现的基础; 为什么会有大量的线程阻塞事务创建时的步骤如下: - 对 trx_sys->mutex 全局上锁;
- 顺序扫描 trx_sys->rw_trx_list,对 read_view 中的元素分配内存并进行赋值,主要包括活跃事务ID的集合的创建,low_limit_id , high_limit_id, low_limit_no 等;
- 将该 read_view 添加到有序列表 trx_sys->view_list中;
- 释放 trx_sys->mutex 锁;
由于read_view 的创建和销毁都需要获取 trx_sys->mutex, 当并发量很大的时候,事务链表会比较长,又由于遍历本身也是一个费时的工作,所以此处便成为了瓶颈,既然我们遇到了这个问题,那么社区应该也有类似的问题。 read view 问题解决过程首先,我们看一下bug#49169,read_view_open_now is inefficient with many concurrent sessions, 即当并发量很大时 read_view_open_now 效率低下的问题,问题的原因主要有以下几个: - 整个创建过程一直持有 trx_sys->mutex 锁;
- read_view 的内存在每次创建中被分配,事务提交后被释放;
- 需要遍历 trx_sys->trx_list (5.5) 或 trx_sys->rw_list (5.6);
- 并发较大,活跃事务链表过长时,会在 trx_sys->mutex 上有较大的消耗;
该 bug 从 MySQL 5.1 的时候被 mrak 大神提出以来,一直到 MySQL 5.7 才被官方完整的解决,其中的解决过程也挺曲折的,另外 Percona 在 5.5 的时候就也推出了解决问题的办法,实现也相对简单好多,但没有 MySQL 5.7 方法的彻底,咱们分别看一下这两种解决方法以及 CDB 内核在这方面的改动。 Percona read view 问题改进Percona 为了解决上述描述的问题,对trx_sys做了以下修改: - 在 trx_sys下维护一个全局的事务ID的有序集合,事务的 创建 & 销毁 的同时将事务的 ID 从这个集合中移除;
- 在 trx_sys下维护一个有序的已分配序列号的事务列表,已记录拥有最小序列号的事务,供 purge 时使用;
- 减少不必要的内存分配,为每一个 trx_t 缓存一个 read_view,read_view 数组的大小根据创建时的活跃全局事务 ID 集合做必要的调整;
做了上面的调整后,事务在创建过程中则不需要遍历 trx_sys->trx_list(version 5.5),直接使用 memcpy 即可获得活跃事务的ID,并且缓存的使用也大大减少了内存的不必要分配; 更详细的信息及源码可以参考 Alexey (sysbench owner, MySQL 另一大神)提交的代码,commit message 详情如下: [AppleScript] 纯文本查看 复制代码 commit e1365c91d04347f1063f8e5a22c1ba2501c4f0d0
Author: Alexey Kopytov <[email]akopytov@gmail.com[/email]>
Date: Mon Mar 25 13:59:39 2013 +0400
Bug #1131189: Remove trx_list scan from read_view_open_now()
The patch introduces a concept if "trx descriptors" which is a global
ordered array containing IDs of transactions in either TRX_ACTIVE or
TRX_PREPARED state. It allows to replace the trx_list scan in
read_view_open_now() and read_cursor_view_create_for_mysql() with a
binary search on the descriptors array and two memcpy()s.
Goals of using the ID array of transactions in certain states:
MySQL read view 问题改进 为了解决 read view 问题,5.6 做了以下几件事情: - 将 5.5 的 trx_list 拆分为 ro_trx_list & rw_trx_list, 由于只读事务不会对数据进行修改,所以在创建视图的同时就只需要扫描 rw_trx_list 即可;
- auto-commit-non-locking-ro transactions 的特殊优化;
- 添加语法 START TRANSACTION READ ONLY 用于声名事务是只读事务;
经过上面的修改,似乎解决了 read view 的问题,但实际却不然,因为他只是解决了事务链表的长度,创建时遍历&内存消耗的开销是没有解决的,并且使用上述特性需要修改应用程序,这一点是比较困难的,因此,5.7为了彻底的解决 read view 的性能问题,做了以下事情: [AppleScript] 纯文本查看 复制代码 1. Refactor the MVCC code
2. Reuse read views for AC-NL-RO selects
3. Use a pool of read views
4. Add MVCC class
5. Use a trx_id to trx_t* map
6. Keep the active trx_id_ts in a vector.
7. Pre-allocate a small cache of record and table locks
8. Avoid extra work when a transaction is tagged as read-only (during commit).
9. General code cleanup
10. Get rid of trx_sys_t::ro_trx_list. Adding and removing a transaction from the ro_trx_list is very costly.
经过了上面的代码重构,5.7 中很少看到 trx_sys->mutex 的性能瓶颈,有想更详细了解的同学可以看一下这些内容: [AppleScript] 纯文本查看 复制代码 WL#6047: [url]http://dev.mysql.com/worklog/task/?id=6047[/url]
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/5209[/url]
WL#6578: [url]http://dev.mysql.com/worklog/task/?id=6578[/url] (部分类似于 Percona 5.6)
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/6203[/url]
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/6204[/url]
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/6205[/url]
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/6224[/url]
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/6236[/url]
[url]http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/6788[/url]
CDB read view 问题改进 为了解决 Read view 的性能问题,简单的说 CDB 内核团队对于Read view 主要做了以下事情: - backport percona 的 read view 相关修改到 CDB MySQL中;
- 参照 5.7 的实现,在 5.6 中将 ro_trx_list 移除;
经过上面的修改彻底的解决了 read_view 的性能问题,在经历了大量 稳定性测试 & 性能测试 后,目前灰度发布中。 线上效果鉴于当前存在的问题,为了解决客户的燃眉之急,决定上一个新版本,和客户联系后,可以重启实例,然后进行了替换操作,替换后的性能效果如下,可以看到 cpu 使用率、load、thread running 降低的同时 QPS + TPS 性能上升,至此问题真正觉得问题应该解决了,余下的就是等客户的反馈了。 [AppleScript] 纯文本查看 复制代码 +---------------------+--------+---------+------------------+------------------+------------------+------------------+---------------+-----------------+---------------------+
| dtime | load_1 | idlecpu | mysql_com_insert | mysql_com_update | mysql_com_delete | mysql_com_select | mysql_com_tps | threads_running | threads_connections |
+---------------------+--------+---------+------------------+------------------+------------------+------------------+---------------+-----------------+---------------------+
| 2016-07-03 22:21:31 | 1.54 | 37.00 | 1995 | 8194 | 0 | 125782 | 10189 | 18 | 1012 |
| 2016-07-03 22:21:32 | 1.54 | 37.00 | 2205 | 8016 | 0 | 125974 | 10221 | 17 | 1012 |
| 2016-07-03 22:21:33 | 1.54 | 49.00 | 2061 | 5758 | 0 | 106469 | 7819 | 25 | 1012 |
| 2016-07-03 22:21:34 | 1.54 | 38.00 | 2450 | 7565 | 0 | 127511 | 10015 | 18 | 1012 |
| 2016-07-03 22:21:35 | 3.66 | 39.00 | 2121 | 6644 | 0 | 128277 | 8765 | 27 | 1012 |
| 2016-07-03 22:21:36 | 3.66 | 41.00 | 2617 | 5966 | 0 | 127987 | 8583 | 22 | 1012 |
| 2016-07-03 22:21:37 | 3.66 | 43.00 | 2009 | 6564 | 0 | 124135 | 8573 | 16 | 1012 |
| 2016-07-03 22:21:38 | 3.66 | 43.00 | 2294 | 5783 | 0 | 123519 | 8077 | 15 | 1012 |
| 2016-07-03 22:21:39 | 4.65 | 45.00 | 2050 | 6931 | 0 | 123719 | 8981 | 13 | 1012 |
| 2016-07-03 22:21:40 | 4.65 | 51.00 | 2039 | 5028 | 0 | 107993 | 7067 | 14 | 1012 |
| 2016-07-03 22:21:41 | 4.65 | 49.00 | 2041 | 5153 | 0 | 110077 | 7194 | 23 | 1012 |
| 2016-07-03 22:21:42 | 4.65 | 49.00 | 2215 | 5347 | 0 | 108539 | 7562 | 24 | 1012 |
| 2016-07-03 22:21:43 | 4.65 | 40.00 | 2000 | 7564 | 0 | 128957 | 9564 | 21 | 1012 |
| 2016-07-03 22:21:45 | 6.84 | 40.00 | 2218 | 6579 | 0 | 129526 | 8797 | 17 | 1012 |
| 2016-07-03 22:21:46 | 6.84 | 49.00 | 1859 | 5800 | 0 | 111708 | 7659 | 18 | 1012 |
| 2016-07-03 22:21:47 | 6.84 | 40.00 | 2098 | 6149 | 0 | 129089 | 8247 | 14 | 1012 |
| 2016-07-03 22:21:48 | 6.84 | 50.00 | 1761 | 4910 | 0 | 112003 | 6671 | 24 | 1012 |
| 2016-07-03 22:21:49 | 6.84 | 40.00 | 2283 | 7195 | 0 | 129313 | 9478 | 20 | 1012 |
| 2016-07-03 22:21:50 | 6.85 | 39.00 | 2394 | 6057 | 0 | 128982 | 8451 | 11 | 1012 |
| 2016-07-03 22:21:51 | 6.85 | 40.00 | 2160 | 5727 | 0 | 128516 | 7887 | 17 | 1012 |
| 2016-07-03 22:21:52 | 6.85 | 41.00 | 2405 | 5628 | 0 | 129897 | 8033 | 16 | 1012 |
| 2016-07-03 22:21:53 | 6.85 | 38.00 | 2072 | 7064 | 0 | 129313 | 9136 | 21 | 1012 |
将监控数据入库,查看峰值 & 当时的负载情况,详情如下:
[AppleScript] 纯文本查看 复制代码 MySQL [sysbench]> select dtime, (mysql_com_tps + mysql_com_select) as total_requests, mysql_com_select, mysql_com_tps, innodb_rows_update, idlecpu,threads_running from ip_10_108_107_97 order by total_requests desc;
+---------------------+----------------+------------------+---------------+--------------------+---------+-----------------+
| dtime | total_requests | mysql_com_select | mysql_com_tps | innodb_rows_update | idlecpu | threads_running |
+---------------------+----------------+------------------+---------------+--------------------+---------+-----------------+
| 2016-07-03 22:15:17 | 170396 | 138029 | 32367 | 32357 | 44.00 | 19 |
| 2016-07-03 22:16:34 | 165842 | 136566 | 29276 | 28919 | 41.00 | 17 |
| 2016-07-03 22:15:14 | 164890 | 135873 | 29017 | 29007 | 43.00 | 16 |
| 2016-07-03 22:15:13 | 163007 | 131839 | 31168 | 31172 | 48.00 | 17 |
| 2016-07-03 22:15:16 | 162658 | 135986 | 26672 | 26687 | 44.00 | 13 |
| 2016-07-03 22:16:37 | 159783 | 134070 | 25713 | 25654 | 45.00 | 12 |
| 2016-07-03 22:16:35 | 156849 | 131101 | 25748 | 25609 | 44.00 | 23 |
| 2016-07-03 22:22:40 | 150488 | 129765 | 20723 | 19930 | 42.00 | 17 |
| 2016-07-03 22:22:38 | 148860 | 130581 | 18279 | 16767 | 39.00 | 25 |
| 2016-07-03 22:22:39 | 148797 | 131086 | 17711 | 16386 | 40.00 | 22 |
| 2016-07-03 22:16:36 | 148189 | 128710 | 19479 | 19418 | 44.00 | 21 |
| 2016-07-03 22:22:36 | 146731 | 129747 | 16984 | 14649 | 38.00 | 21 |
| 2016-07-03 22:22:37 | 145356 | 129450 | 15906 | 13810 | 39.00 | 24 |
| 2016-07-03 21:20:12 | 145331 | 128423 | 16908 | 15068 | 44.00 | 19 |
| 2016-07-03 21:20:10 | 145252 | 131791 | 13461 | 10909 | 43.00 | 10 |
| 2016-07-03 21:20:14 | 145200 | 127102 | 18098 | 17107 | 48.00 | 18 |
| 2016-07-03 21:19:09 | 144442 | 135123 | 9319 | 5555 | 42.00 | 19 |
| 2016-07-03 22:22:34 | 144181 | 129076 | 15105 | 12345 | 39.00 | 16 |
| 2016-07-03 22:22:33 | 143299 | 129232 | 14067 | 11302 | 39.00 | 15 |
| 2016-07-03 22:23:44 | 142831 | 130274 | 12557 | 10118 | 42.00 | 21 |
| 2016-07-03 21:19:10 | 142181 | 131958 | 10223 | 6051 | 43.00 | 18 |
| 2016-07-03 21:21:02 | 142168 | 120097 | 22071 | 21667 | 44.00 | 16 |
遗留问题 & 展望
真的完美了吗,其实不是这样的,我们还有很多的事情要做,因为在解决问题的过程中,我们通过 pstack & pt-pmp 抓到了很多有用的信息,有一些是暂时没有解决的,如: - innodb 内部表锁冲突严重;
- MDL Lock 即使扩大也存在着不小的影响;
- 内存分配也有一些需要优化的地方;
- 执行计划的计算代价比较高;
- thread running 彪高时没有可以控制的方法;
- ….
由于时间问题我们暂时将遇到的问题一一记下,一个一个解决,我们相信 CDB 的内核会越来越强大,在提升性能的同时也不断的提升稳定性,我们一步一步踏在当下,努力让 CDB 变得更好!
|