Delete some records of MySQLLogs

Before May 1, a DBA reported that a large slow log file was deleted in the daily environment (assuming the file size is more than 10 GB ), then execute flush slow logs in MySQL and you will find mysqld hang.

I tried to reproduce this problem today. here I will briefly analyze the cause.

Reproduction steps:

1. construct the slow log (set long_query_time to 0 );

2. observe the tps/qps changes when rm slow log is deleted;

3. observe the changes in tps/qps when the flush slow logs is executed;

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

The first step is nothing to say.

Step 2: tps/qps remains unchanged.

Step 3: tps/qps instantly drops to 0, 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

Mysql command line shows that the execution time of flush slow logs is about 3 seconds.

Step 4: Let's take a look at the pstack output result and record only the relevant:

610 Thread 5 (Thread 0x2afdc4101700 (LWP 30762)):611 #00x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0612 #10x0000000000825135 in inline_mysql_rwlock_rdlock ()613 #20x0000000000838004 in LOGGER::lock_shared() ()614 #30x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()615 #40x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()616 #50x0000000000609f23 in log_slow_statement(THD*) ()617 #60x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()618 #70x0000000000606e02 in do_command(THD*) ()619 #80x00000000006f070f in do_handle_one_connection(THD*) ()620 #90x00000000006f020d in handle_one_connection ()621 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0622 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6623 Thread 4 (Thread 0x2afdd0080700 (LWP 30763)):624 #00x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0625 #10x0000000000825135 in inline_mysql_rwlock_rdlock ()626 #20x0000000000838004 in LOGGER::lock_shared() ()627 #30x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()628 #40x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()629 #50x0000000000609f23 in log_slow_statement(THD*) ()630 #60x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()631 #70x0000000000606e02 in do_command(THD*) ()632 #80x00000000006f070f in do_handle_one_connection(THD*) ()633 #90x00000000006f020d in handle_one_connection ()634 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0635 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6636 Thread 3 (Thread 0x2afdd0101700 (LWP 30764)):637 #00x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0638 #10x0000000000825135 in inline_mysql_rwlock_rdlock ()639 #20x0000000000838004 in LOGGER::lock_shared() ()640 #30x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()641 #40x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()642 #50x0000000000609f23 in log_slow_statement(THD*) ()643 #60x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()644 #70x0000000000606e02 in do_command(THD*) ()645 #80x00000000006f070f in do_handle_one_connection(THD*) ()646 #90x00000000006f020d in handle_one_connection ()647 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0648 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6649 Thread 2 (Thread 0x2afe18080700 (LWP 30855)):650 #00x0000003c6e40e54d in close () from /lib64/libpthread.so.0651 #10x00000000008f56ed in my_close ()652 #20x0000000000825c16 in inline_mysql_file_close ()653 #30x000000000082b305 in MYSQL_LOG::close(unsigned int) ()654 #40x000000000082b634 in MYSQL_QUERY_LOG::reopen_file() ()655 #50x0000000000828283 in LOGGER::flush_slow_log() ()656 #60x000000000071d8fc in reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) ()657 #70x0000000000610200 in mysql_execute_command(THD*) ()658 #80x000000000061534d in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()659 #90x00000000006086a0 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.0664 #14 0x0000003c6e0e570d in clone () from /lib64/libc.so.6

Thread 2 is executing the flush slow logs operation. other threads are waiting for the LOCK_log lock.

The reason is actually very simple. when executing the rm slow log operation in shell, the file is not deleted because mysqld still has a file handle to open the file. Execute the flush logs operation. the actual execution is 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.

During deletion, the system will execute dirty clicks (of course, I constructed this scenario very extreme, basically all the content of slow log files is in the file system cache), which will consume a lot of time, for example, it takes 3 s to execute this statement. During this period, if the statements sent by the connection need to be logged (the server layer log: slow log/binlog/general log has a total of LOCK_log locks), they will be in the waiting state, then the system's external response is hang.

The time required for calling and executing close in flush slow logs is related to the file size and the ratio of dirty pages in the file system cache. for example, I used sysctl vm before executing flush slow logs. drop_caches = 3 clear

If the file system cache is used, the execution time of flush slow logs operations of the same size is 0.42 s, and the corresponding blocking time will be reduced a lot.

You can consider executing the posix_fadvise call on the slow logs file handle to avoid caching large log file content (slow logs do not need to be cached). This is a master's article, refer to posix_fadvise's misunderstanding and improvement measures for clearing the cache.

In addition, peter discussed this issue in. Be careful rotating MySQL logs recommended that you first perform the mv file, then flush logs, and then delete the file, let the real deletion behavior be done by yourself rather than mysqld. Unfortunately, five years later, LOCK_log has not completely solved the lock problem.

PS:

At the end of this article, remember to delete a 10 GB file by using the close/rm operation. drop_caches = 3 after the cache is cleared, this operation takes hundreds of milliseconds (200 ms + on my machine ), you need to find out the kernel group's colleagues.