Bug #104666 flush logs ( FLUSH RELAY LOGS ) taking forever and it is in starting state
Submitted: 19 Aug 2021 13:47 Modified: 23 Aug 2021 12:29
Reporter: Trimurthy Pothanaboyina Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:8.0.25 OS:SUSE (SUSE Linux Enterprise Server 12 SP5)
Assigned to: CPU Architecture:x86 (x86_64)

[19 Aug 2021 13:47] Trimurthy Pothanaboyina
Description:
Flush logs taking forever and it is in starting state.

As flush logs implicitly calls different flush commands only FLUSH RELAY LOGS is having issue. Rest all working fine without any issues. 

Working : 
FLUSH BINARY LOGS
FLUSH ENGINE LOGS
FLUSH ERROR LOGS
FLUSH GENERAL LOGS
FLUSH SLOW LOGS

Not Working:
FLUSH RELAY LOGS

The following is the show process list captured from the database.
mysql> show processlist;
+------+-------------+---------------------------------------+-------------+-------------+-------+---------------------------------------------------------------+------------------+
| Id   | User        | Host                                  | db          | Command     | Time  | State                                                         | Info             |
+------+-------------+---------------------------------------+-------------+-------------+-------+---------------------------------------------------------------+------------------+
|    6 | system user | connecting host                       | NULL        | Connect     | 20367 | Queueing master event to the relay log                        | NULL             |
|    9 | monitoring  | hostname:40684                      	 | NULL        | Sleep       |     2 |                                                               | NULL             |
|  331 | app_user    | hostname:55260 						 | app_database| Sleep       |    14 |                                                               | NULL             |
|  332 | app_user    | hostname:55262 						 | app_database| Sleep       |    47 |                                                               | NULL             |
|  351 | monitoring  | hostname:44182                      	 | NULL        | Sleep       |    25 |                                                               | NULL             |
|  354 | app_user    | hostname:50434 						 | app_database| Sleep       |    14 |                                                               | NULL             |
|  355 | app_user    | hostname:50436 						 | app_database| Sleep       |    38 |                                                               | NULL             |
|  381 | app_user    | hostname:53316 						 | app_database| Sleep       |    14 |                                                               | NULL             |
|  382 | app_user    | hostname:53318 						 | app_database| Sleep       |   117 |                                                               | NULL             |
|  383 | app_user    | hostname:53320 						 | app_database| Sleep       |   279 |                                                               | NULL             |
|  999 | dbadminuser | localhost                             | mysql       | Killed      | 12266 | starting                                                      | flush logs       |
| 1099 | dbadminuser | localhost                             | mysql       | Query       | 11388 | starting                                                      | flush logs       |
| 1221 | dbadminuser | localhost                             | mysql       | Query       | 10487 | starting                                                      | flush logs       |
| 1334 | dbadminuser | localhost                             | mysql       | Query       |  9588 | starting                                                      | flush logs       |
| 1433 | root        | localhost                             | sys         | Query       |  7425 | waiting for handler commit                                    | stop slave       |
| 1454 | dbadminuser | localhost                             | mysql       | Query       |  8691 | starting                                                      | flush logs       |
| 1566 | dbadminuser | localhost                             | mysql       | Query       |  7787 | starting                                                      | flush logs       |
| 1624 | repl_user   | hostname:33896 						 | NULL        | Binlog Dump |  7399 | Master has sent all binlog to slave; waiting for more updates | NULL             |
| 1628 | root        | localhost                             | NULL        | Query       |  6949 | starting                                                      | start slave      |
| 1685 | root        | localhost                             | NULL        | Query       |  4252 | starting                                                      | FLUSH RELAY LOGS |
| 1687 | dbadminuser | localhost                             | mysql       | Query       |  6877 | starting                                                      | flush logs       |
| 1798 | dbadminuser | localhost                             | mysql       | Query       |  5985 | starting                                                      | flush logs       |
| 1913 | dbadminuser | localhost                             | mysql       | Query       |  5085 | starting                                                      | flush logs       |
| 2024 | dbadminuser | localhost                             | mysql       | Query       |  4183 | starting                                                      | flush logs       |
| 2141 | dbadminuser | localhost                             | mysql       | Query       |  3285 | starting                                                      | flush logs       |
| 2250 | dbadminuser | localhost                             | mysql       | Query       |  2383 | starting                                                      | flush logs       |
| 2349 | monitoring  | hostname:62411                     	 | NULL        | Sleep       |     0 |                                                               | NULL             |
| 2438 | monitoring  | hostname:58438                     	 | NULL        | Sleep       |    46 |                                                               | NULL             |
| 2497 | monitoring  | hostname:49979                     	 | NULL        | Sleep       |    18 |                                                               | NULL             |
| 2549 | root        | localhost                             | NULL        | Query       |     0 | init                                                          | show processlist |
+------+-------------+---------------------------------------+-------------+-------------+-------+---------------------------------------------------------------+------------------+

How to repeat:
The same behavior observed in 2 different master-master replication servers running on MySQL 8.0.25 and we are not able to reproduce the issue manually. 

Suggested fix:
NA
[19 Aug 2021 13:54] Trimurthy Pothanaboyina
The following are the flush commands with their respective status. Ran the following commands while flush logs sessions already running more than an hour. 
And also stop slave & start slave commands are also not working during this situation.

mysql> FLUSH BINARY LOGS;
Query OK, 0 rows affected (0.09 sec)

mysql> FLUSH ENGINE LOGS;
Query OK, 0 rows affected (0.00 sec)

mysql> FLUSH ERROR LOGS;
Query OK, 0 rows affected (0.03 sec)

mysql> FLUSH GENERAL LOGS;
Query OK, 0 rows affected (0.00 sec)

mysql> FLUSH SLOW LOGS;
Query OK, 0 rows affected (0.09 sec)

mysql> FLUSH RELAY LOGS;

^C^C -- sending "KILL QUERY 1685" to server ...
^C -- query aborted
^C^C -- sending "KILL QUERY 1685" to server ...
^C -- query aborted
^Z
[3]+  Stopped
[23 Aug 2021 12:29] MySQL Verification Team
Hi Mr. pothanaboyina,

Thank you for your bug report.

However, it is not a bug.

Flushing binary and relay logs depends totally on the locks that are set by InnoDB and other storage engines. Hence, flushing those logs has to wait for all the foreground transactions and backgrounds threads to finish their work, before these logs can be flushed.

Hence, not a bug.