Shulou(Shulou.com)06/01 Report--

This article will explain in detail how to solve the problem of MySQL Logs, the content of the article is of high quality, so the editor will share it with you for reference. I hope you will have a certain understanding of the relevant knowledge after reading this article.

Before May Day, a DBA colleague reported that deleting a large slow log file in the daily environment (assuming the file size is more than 10G), and then performing flush slow logs in MySQL, you will find that mysqld hang lives.

We tried to reproduce this problem today, and here is a brief analysis of the reasons.

Reproduce steps:

1. Construct slow log (set long_query_time to 0)

two。 Observe the instant of deleting RM slow log, tps/qps changes

3. Observe the change of tps/qps at the moment when flush slow logs is executed

4. Record the call stack made by pstack during the execution of flush slow logs

Step one, there's nothing to say.

Step two, tps/qps has not changed much.

In the third step, you will find that tps/qps drops by 0 in an instant, as shown below:

[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

The mysql command line will find that the flush slow logs execution time is exactly about 3 seconds.

Step 4, let's take a look at the output of pstack and record only the relevant ones:

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. 0625 # 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. 0638 # 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

You will find that Thread 2 is performing the flush slow logs operation, and the other threads are waiting for the lock LOCK_log.

The reason behind this is actually very simple: when performing a rm slow log operation in shell, because mysqld still has a file handle to open the file, the file is not actually deleted at this time. When the flush logs operation is performed, it actually performs the 1) close;2) open operation (logger.flush_slow_log-> mysql_slow_log.reopen_file). When the close operation is executed, the file system actually deletes the file, and the thread occupies the LOCK_log lock.

Scrubbing is performed when deleting (of course, I construct this scenario at the extreme, where almost all the contents of slow log files are in the file system cache), which can be time-consuming, for example, it took me 3 seconds to execute this statement. During this period of time, if the statement sent by the connection needs to remember log (the log:slow log/binlog/general log of the server layer shares the LOCK_log lock), it will be in a waiting state, then the external response of the system is that the hang resides.

The time it takes to call close in flush slow logs is related to the file size and the percentage of dirty pages in the file system cache. For example, I use sysctl vm.drop_caches=3 to clear the file before executing flush slow logs.

If the file system is cached, the execution time of flush slow logs operations of the same size is 0.42 seconds, and the corresponding blocking time will be greatly reduced.

You can consider performing a posix_fadvise call on the file handle of slow logs to prevent large log file contents from being cached (slow log does not need to be cached). Here is a bully's article, you can refer to posix_fadvise 's misunderstandings and improvement measures to clean up the cache.

In addition, peter discussed this issue in 2007, and Be careful rotating MySQL logs's suggestion is to mv file first, then flush logs, and then delete files, so that the real deletion is done by yourself rather than mysqld. Unfortunately, seven years later, the problem of LOCK_log lock has not been completely solved.

A note at the end of the article: delete a 10G file through the close/rm operation. After performing sysctl vm.drop_caches=3 to clear the cache, this operation still takes 100 milliseconds (200ms + on my machine). What is done behind it needs to be known to my colleagues in the kernel group.

On how to solve the problem of MySQL Logs to share here, I hope that the above content can be of some help to you, can learn more knowledge. If you think the article is good, you can share it for more people to see.

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.