关于删除MySQL Logs的一点记录 - 刘浩de技术博客

标签: 删除 mysql logs | 发表时间:2014-05-04 15:16 | 作者:刘浩de技术博客
出处:

五一前,一个DBA同事反馈,在日常环境中删除一个大的slow log文件(假设文件大小10G以上吧),然后在MySQL中执行flush slow logs,会发现mysqld hang住。

 

今天尝试着重现了此问题,这里简要分析下原因。

 

重现步骤:

1. 构造slow log (将long_query_time设成了0);

2. 观察删rm slow log瞬间,tps/qps变化;

3. 观察执行flush slow logs瞬间,tps/qps变化;

4. 记录flush slow logs执行时, pstack打出的调用栈情况;

 

第一步,没啥好说的。

第二步,tps/qps没啥变化。

第三步,会发现tps/qps瞬间跌0,如下所示:

[ 639s] threads: 32, tps: 1121.00, reads/s: 15843.98, writes/s: 4490.99
[ 640s] threads: 32, tps: 792.99, reads/s: 10803.89, writes/s: 3150.97
[ 641s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 0.00
[ 642s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 0.00
[ 643s] threads: 32, tps: 471.01, reads/s: 6860.08, writes/s: 1908.02

mysql命令行会发现,flush slow logs执行时间刚好为3s左右。

第四步,我们看下pstack的输出结果,只记录相关的:

610 Thread 5 (Thread 0x2afdc4101700 (LWP 30762)):
611 #0 0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
612 #1 0x0000000000825135 in inline_mysql_rwlock_rdlock ()
613 #2 0x0000000000838004 in LOGGER::lock_shared() ()
614 #3 0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
615 #4 0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
616 #5 0x0000000000609f23 in log_slow_statement(THD*) ()
617 #6 0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
618 #7 0x0000000000606e02 in do_command(THD*) ()
619 #8 0x00000000006f070f in do_handle_one_connection(THD*) ()
620 #9 0x00000000006f020d in handle_one_connection ()
621 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
622 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6

623 Thread 4 (Thread 0x2afdd0080700 (LWP 30763)):
624 #0 0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
625 #1 0x0000000000825135 in inline_mysql_rwlock_rdlock ()
626 #2 0x0000000000838004 in LOGGER::lock_shared() ()
627 #3 0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
628 #4 0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
629 #5 0x0000000000609f23 in log_slow_statement(THD*) ()
630 #6 0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
631 #7 0x0000000000606e02 in do_command(THD*) ()
632 #8 0x00000000006f070f in do_handle_one_connection(THD*) ()
633 #9 0x00000000006f020d in handle_one_connection ()
634 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
635 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6

636 Thread 3 (Thread 0x2afdd0101700 (LWP 30764)):
637 #0 0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
638 #1 0x0000000000825135 in inline_mysql_rwlock_rdlock ()
639 #2 0x0000000000838004 in LOGGER::lock_shared() ()
640 #3 0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
641 #4 0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
642 #5 0x0000000000609f23 in log_slow_statement(THD*) ()
643 #6 0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
644 #7 0x0000000000606e02 in do_command(THD*) ()
645 #8 0x00000000006f070f in do_handle_one_connection(THD*) ()
646 #9 0x00000000006f020d in handle_one_connection ()
647 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
648 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6

649 Thread 2 (Thread 0x2afe18080700 (LWP 30855)):
650 #0 0x0000003c6e40e54d in close () from /lib64/libpthread.so.0
651 #1 0x00000000008f56ed in my_close ()
652 #2 0x0000000000825c16 in inline_mysql_file_close ()
653 #3 0x000000000082b305 in MYSQL_LOG::close(unsigned int) ()
654 #4 0x000000000082b634 in MYSQL_QUERY_LOG::reopen_file() ()
655 #5 0x0000000000828283 in LOGGER::flush_slow_log() ()
656 #6 0x000000000071d8fc in reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) ()
657 #7 0x0000000000610200 in mysql_execute_command(THD*) ()
658 #8 0x000000000061534d in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()
659 #9 0x00000000006086a0 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
660 #10 0x0000000000606e02 in do_command(THD*) ()
661 #11 0x00000000006f070f in do_handle_one_connection(THD*) ()
662 #12 0x00000000006f020d in handle_one_connection ()
663 #13 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
664 #14 0x0000003c6e0e570d in clone () from /lib64/libc.so.6

会发现Thread 2在执行flush slow logs操作,其他的线程都在等待锁LOCK_log上边。

 

背后的原因其实很简单,在shell中执行rm slow log操作时,由于mysqld仍有文件句柄打开此文件,所以实际上此时文件并未删除。执行flush logs操作,其实际执行的是1)close;2)open 操作(logger.flush_slow_log -> mysql_slow_log.reopen_file),在close操作执行时,文件系统真正删除文件,此时该线程占用着LOCK_log锁。

删除时会执行刷脏(当然我构造这个场景很极端,基本所有slow log文件的内容都在文件系统缓存中),这个会很耗时间,比如我执行这个语句耗了3s。此时间段内,如果连接发来的语句需要记log(server层的log:slow log/binlog/general log共有LOCK_log这把锁)就会处于等待状态,那么系统对外的反应就是hang住了。

 

flush slow logs中调用执行的close所需时间和文件大小、以及文件系统缓存中该文件脏页比例都有关系,比如我在执行flush slow logs前使用sysctl vm.drop_caches=3清空

了文件系统缓存的话,同样大小的flush slow logs操作执行时间是0.42s,相应的阻塞时间也会减少不少。

可以考虑在slow logs的文件句柄上执行posix_fadvise调用,促使不会缓存很大的log文件内容(slow log也没啥需要缓存的),这有篇霸爷的文章,可以参考下  posix_fadvise清除缓存的误解和改进措施 。

另外,peter在07年就讨论过这个问题,  Be careful rotating MySQL logs 其给出的建议是先mv file,然后flush logs,再执行删除文件的操作,让真正的删除行为由自己而不是mysqld完成。比较遗憾的是,五年过去了,LOCK_log这把锁的问题还没有完整的解决掉。

 

PS:

文章结尾记一点备忘,通过close/rm操作删除一个10G大小的文件,在执行sysctl vm.drop_caches=3清空缓存后,此操作的耗时仍在百毫秒量级(我的机器上是200ms+),其背后做了什么事情还需要找内核组的同事了解下。

 


本文链接: 关于删除MySQL Logs的一点记录,转载请注明。

相关 [删除 mysql logs] 推荐:

关于删除MySQL Logs的一点记录 - 刘浩de技术博客

- - 博客园_首页
五一前,一个DBA同事反馈,在日常环境中删除一个大的slow log文件(假设文件大小10G以上吧),然后在MySQL中执行flush slow logs,会发现mysqld hang住. 今天尝试着重现了此问题,这里简要分析下原因. 构造slow log (将long_query_time设成了0);.

mysql删除大表更快的drop table办法

- 胖岁 - haohtml's blog
曾经发文介绍过,DROP table XXX ,特别是碰到大表时,. 在DROP TABLE 过程中,所有操作都会被HANG住. 这是因为INNODB会维护一个全局独占锁(在table cache上面),直到DROP TABLE完成才释放. 在我们常用的ext3,ext4,ntfs文件系统,要删除一个大文件(几十G,甚至几百G)还是需要点时间的.

Linux下自动备份MySQL数据库并上传到远程FTP服务器且删除指定日期前的备份Shell脚本

- - CSDN博客数据库推荐文章
1、备份MySQL数据库存放目录/var/lib/mysql下面的vos3000db数据库到/home/mysql_data里面,并且保存为vos3000db_bak_2012_06_30.tar.gz的压缩文件格式(2012_06_30是指备份执行时当天的日期),最后只保留最近7天的备份. 2、上传/home/mysql_data里面的备份文件到远程FTP服务器上,并且只保留最近7天的备份.

Hibernate级联删除

- - CSDN博客推荐文章
如果cascade属性是默认值"none",当hibernate删除一个持久化对象的时候,不会自动删除与它关联的其他持久化对象. 如果希望自动删除它关联的其他持久化对象,可以把casacde属性设为"delete";. 那么hibernate在删除一个Shool对象时,实际执行的SQL是:. 作者:howlaa 发表于2013-9-29 20:37:17 原文链接.

Js删除节点

- - JavaScript - Web前端 - ITeye博客
 方式一:传this参数调用方法:.  方式二:js方法中通过选择器获取节点:. //此处删除的是a节点 }. 方式三:通过jQuery方式获取节点:(尚未测试,有待测试. 此处a标签传this到js中,js通过this(即a节点)取parent(即p节点). (1)p.remove();可直接删除整个p节点.

Linux Ksplice,MySQL and Oracle

- Syn - DBA Notes
Oracle 在 7 月份收购了 Ksplice. 使用了 Ksplice 的 Linux 系统,为 Kernel 打补丁无需重启动,做系统维护的朋友应该明白这是一个杀手级特性. 现在该产品已经合并到 Oracle Linux 中. 目前已经有超过 700 家客户,超过 10 万套系统使用了 Ksplice (不知道国内是否已经有用户了.

MySQL Replication 线程

- - CSDN博客推荐文章
Replication 线程. Mysql 的Replication 是一个异步的复制过程,从一个Mysql instace(我们称之为Master)复制到另一个Mysql instance(我们称之Slave). 在Master 与Slave 之间的实现整个复制过程主. 要由三个线程来完成,其中两个线程(Sql 线程和IO 线程)在Slave 端,另外一个线程(IO 线程)在Master 端.

mysql backup 脚本

- - ITeye博客
网上备份脚本很多,但考虑都不周全. 保证创建备份文件只能是创建者跟root可以访问,其他用户没有权限,保证了数据库备份的安全. 上面脚本是负责备份的份数管理,. 已有 0 人发表留言,猛击->> 这里<<-参与讨论. —软件人才免语言低担保 赴美带薪读研.

Oracle MySQL Or NoSQL续

- - Sky.Jian 朝阳的天空
接前面一篇,这里再将之前在“中国系统架构师大会”5周年的时候发布的纪念册“IT架构实录”上的一篇文章发出来,也算是前面博文中PPT的一个文字版解读吧. Oracle,MySQL 还是 NoSQL. 随着阿里系的“去IOE”运动在社区的宣传声越来越大,国内正在掀起一股“去xxx”的技术潮. 不仅仅是互联网企业,包括运营商以及金融机构都已经开始加入到这个潮流之中.

mysql优化

- - 数据库 - ITeye博客
公司网站访问量越来越大,MySQL自然成为瓶颈,因此最近我一直在研究 MySQL  的优化,第一步自然想到的是 MySQL 系统参数的优化,作为一个访问量很大的网站(日20万人次以上)的数据库系统,不可能指望 MySQL  默认的系统参数能够让 MySQL运行得非常顺畅. 在Apache, PHP,  MySQL的体系架构中,MySQL对于性能的影响最大,也是关键的核心部分.