已经有一段时间没有分享了。不过,这次冒泡,却不是技术分享,是求助。
前段时间发现,我们的一个某系统数据库,数据库版本5.7.18,存在mysqld进程使用的内存慢慢往上涨的情况,感觉没有一个天花板,持续缓慢地增长,没有刹车的迹象。愁,,,,,
简单的介绍一下数据库的环境:表特别多,大概两万三千到五千多张,数据量也比较大,接近300G,这些数据几乎都会被访问到,基本都是活跃数据。 数据库内存128G,设置了60多G的innodb buffer pool . 因为表的数量比较多,所以设置的table_cache比较大,350000,实际缓存的table数量也比较多,跟这个数量非常接近,但实际上,虚拟内存使用到了114G,比buffer pool多出了50多G, 实际占用内存也到了102G,但还是有缓慢增长的迹象。需要特别说明的是:这里仅介绍一下环境,目前没有发现证据或者理论依据证明,内存缓慢的往上蹭,跟数据量大或者表的数量多有直接的关系。 如果有朋友也发现类似现象,希望可以一起讨论。如果有高手指点,那就更棒了。
从海量的mysql代码中,找内存缓慢增长的原因,其实有点像大海捞针。为了跟踪内存分配与释放,先跟踪了heap内存的分配跟释放,无结果。后来,直接跟踪更底层的函数,物理内存的分配跟释放。 但仅仅跟踪了内存的分配跟释放,虽然知道是哪个内存没释放,但不知道到底是谁申请的,有何用途。所以把分配内存函数的栈也打了出来,但问题又来了,持续进行流量测试,产生的日志量巨大,第一造成空间不足,第二后续分析困难。 手工测试某个sql,却又没有发现非常值得怀疑的异常。 悲剧。
下面是作者在跟踪内存分配时打出来的日志:
xcy_ma_exit ptr: 0x7f7df000e1b0stack_bottom = 0 thread_stack 0x0/mysql/myinst1/service/bin/mysqld(my_print_stacktrace+0x35)[0x18c76d8]/mysql/myinst1/service/bin/mysqld[0x18c1fc4]/mysql/myinst1/service/bin/mysqld(my_malloc+0x2f)[0x18c19fd]/mysql/myinst1/service/bin/mysqld(my_strdup+0x3a)[0x18c2278]/mysql/myinst1/service/bin/mysqld(my_register_filename+0xfd)[0x18c2f13]/mysql/myinst1/service/bin/mysqld(my_open+0xbc)[0x18c2bae]/mysql/myinst1/service/bin/mysqld[0x1828b1f]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG4openEjPKcS1_+0x150)[0x182ef84]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG11open_binlogEPKcS1_mbbbP28Format_description_log_event+0x33e)[0x1831e58]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG13new_file_implEbP28Format_description_log_event+0x75c)[0x183677a]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG24new_file_without_lockingEP28Format_description_log_event+0x25)[0x183601b]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG6rotateEbPb+0x101)[0x1837c65]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG16rotate_and_purgeEP3THDb+0xab)[0x1837e13]/mysql/myinst1/service/bin/mysqld(_Z20reload_acl_and_cacheP3THDmP10TABLE_LISTPi+0x33a)[0x15d6d0b]/mysql/myinst1/service/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x4b3d)[0x1597c7b]/mysql/myinst1/service/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x53a)[0x159b5f4]/mysql/myinst1/service/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xc20)[0x1590d5e]/mysql/myinst1/service/bin/mysqld(_Z10do_commandP3THD+0x4b2)[0x158fc50]/mysql/myinst1/service/bin/mysqld(handle_connection+0x1e0)[0x16bf568]/mysql/myinst1/service/bin/mysqld(pfs_spawn_thread+0x170)[0x1d36da5]/lib64/libpthread.so.0(+0x8734)[0x7f7f00cff734]/lib64/libc.so.6(clone+0x6d)[0x7f7eff74fd3d]xcy_finish_ma_exit ptr: 0x7f7df000e1b0
上面是分配内存地址0x7f7df000e1b0 的栈,有flush logs命令触发binlog的rotate.
xcy_my_free ptr: 0x7f7df000e1b0stack_bottom = 0 thread_stack 0x0/mysql/myinst1/service/bin/mysqld(my_print_stacktrace+0x35)[0x18c76d8]/mysql/myinst1/service/bin/mysqld[0x18c2140]/mysql/myinst1/service/bin/mysqld(my_free+0x90)[0x18c1d48]/mysql/myinst1/service/bin/mysqld(my_close+0x1db)[0x18c2da2]/mysql/myinst1/service/bin/mysqld[0x1828bbe]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG5closeEj+0x388)[0x18390f6]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG13new_file_implEbP28Format_description_log_event+0x5f3)[0x1836611]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG24new_file_without_lockingEP28Format_description_log_event+0x25)[0x183601b]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG6rotateEbPb+0x101)[0x1837c65]/mysql/myinst1/service/bin/mysqld(_ZN13MYSQL_BIN_LOG16rotate_and_purgeEP3THDb+0xab)[0x1837e13]/mysql/myinst1/service/bin/mysqld(_Z20reload_acl_and_cacheP3THDmP10TABLE_LISTPi+0x33a)[0x15d6d0b]/mysql/myinst1/service/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x4b3d)[0x1597c7b]/mysql/myinst1/service/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x53a)[0x159b5f4]/mysql/myinst1/service/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xc20)[0x1590d5e]/mysql/myinst1/service/bin/mysqld(_Z10do_commandP3THD+0x4b2)[0x158fc50]/mysql/myinst1/service/bin/mysqld(handle_connection+0x1e0)[0x16bf568]/mysql/myinst1/service/bin/mysqld(pfs_spawn_thread+0x170)[0x1d36da5]/lib64/libpthread.so.0(+0x8734)[0x7f7f00cff734]/lib64/libc.so.6(clone+0x6d)[0x7f7eff74fd3d]xcy_finish_my_free ptr: 0x7f7df000e1b0
上面是释放内存0x7f7df000e1b0的栈, 进行第二次flush logs的时候,会关闭之前的binlog,然后释放之前分配内存。
查看某个内存地址所有的分配/释放记录
MYSQ4TMP:/mysqldata/myinst1/log # grep "0x7f7df000e1b0" error.logxcy_ma_exit ptr: 0x7f7df000e1b0 xcy_finish_ma_exit ptr: 0x7f7df000e1b0 xcy_my_free ptr: 0x7f7df000e1b0 xcy_finish_my_free ptr: 0x7f7df000e1b0
上面仅仅是一个例子,通过这种方法来跟踪所有内存的分配跟释放。然并卵,依然没有找到内存造成内存增长的原因。
唯一发现一个可能会造成内存大量增长的问题,在mysql .5.7.21 已经修复,但跟我们的现象无关。
InnoDB: An iterative approach to processing foreign cascade operations resulted in excessive memory use. (Bug #26191879, Bug #86573)
References: This issue is a regression of: Bug #16244691.
官方修正该bug,涉及主要改动的代码如下:
。。。。。。。。。。。。。。。。。。。。。。
修改因为外键约束而需要级联修改的部分, 使用外键级联功能的朋友,如果升级到5.7.21, 可以好好测试一下这部分功能,这部分改动蛮大的。