MySQL Bugs: #78777: Threads staying in "cleaning up" state forever

Bug #78777	Threads staying in "cleaning up" state forever
Submitted:	9 Oct 2015 9:39	Modified:	11 Aug 2016 17:25
Reporter:	Przemyslaw Malkowski	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.7.8, 5.6.27, 5.7.10	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
The documentation https://dev.mysql.com/doc/refman/5.7/en/general-thread-states.html states:
"cleaning up

The thread has processed one command and is preparing to free memory and reset certain state variables. "

It does not say anything if these thread states descriptions apply to both the processlist and 'show engine innodb status' - 'TRANSACTIONS' part, but I assume they do. However it happens that often the state in both places, for the same thread, differs.

In at least the following situations, the 'cleaning up' states sticks to a thread forever, even though it being completely idle:
1 - an active but idle transaction holding some row locks,
2 - any connection that has read or write an InnoDB table, even though transaction is committed.

Both cases happen for MySQL 5.6 while it seems that for MySQL 5.7, only the first one.

How to repeat:
-- first case

session1 > select @@version;
+-----------+
| @@version |
+-----------+
| 5.7.8-rc  |
+-----------+
1 row in set (0.00 sec)

session1 > begin; select id from db1.t1 for update;
Query OK, 0 rows affected (0.00 sec)

+------+
| id   |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

session2 >pager grep -A5 TRANSACTIONS
PAGER set to 'grep -A5 TRANSACTIONS'
session2 >show engine innodb status\G
TRANSACTIONS
------------
Trx id counter 1802
Purge done for trx's n:o < 1801 undo n:o < 0 state: running but idle
History list length 8
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422212158105408, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 1801, ACTIVE 34 sec
2 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 2, OS thread handle 140736596367104, query id 51 localhost msandbox cleaning up
1 row in set (0.00 sec)

session2 >nopager
PAGER set to stdout
session2 >select * from information_schema.innodb_trx\G                                                                                                                                                                                                                        *************************** 1. row ***************************
                    trx_id: 1801
                 trx_state: RUNNING
               trx_started: 2015-10-09 04:40:03
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 2
       trx_mysql_thread_id: 2
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 2
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 10000
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
1 row in set (0.00 sec)

session2 >select * from information_schema.processlist;
+----+----------+-----------+------+---------+------+-----------+----------------------------------------------+
| ID | USER     | HOST      | DB   | COMMAND | TIME | STATE     | INFO                                         |
+----+----------+-----------+------+---------+------+-----------+----------------------------------------------+
|  2 | msandbox | localhost | NULL | Sleep   |  140 |           | NULL                                         |
|  3 | msandbox | localhost | NULL | Query   |    0 | executing | select * from information_schema.processlist |
+----+----------+-----------+------+---------+------+-----------+----------------------------------------------+
2 rows in set (0.01 sec)

-- second case

session1 > select @@version;
+-----------+
| @@version |
+-----------+
| 5.6.27    |
+-----------+
1 row in set (0.00 sec)

session1 > select * from test.t1;
Empty set (0.00 sec)

session2 > pager grep -A5 TRANSACTIONS
PAGER set to 'grep -A5 TRANSACTIONS'
session2 > show engine innodb status\G
TRANSACTIONS
------------
Trx id counter 1805
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 1804, not started
MySQL thread id 6, OS thread handle 0x7fffcec83700, query id 391 localhost msandbox cleaning up
---TRANSACTION 0, not started
MySQL thread id 4, OS thread handle 0x7fffcecc4700, query id 394 localhost msandbox init
show engine innodb status
1 row in set (0.00 sec)

session2 > nopager
PAGER set to stdout
session2 > show processlist;
+----+----------+-----------+------+---------+------+-------+------------------+
| Id | User     | Host      | db   | Command | Time | State | Info             |
+----+----------+-----------+------+---------+------+-------+------------------+
|  4 | msandbox | localhost | NULL | Query   |    0 | init  | show processlist |
|  6 | msandbox | localhost | NULL | Sleep   |  105 |       | NULL             |
+----+----------+-----------+------+---------+------+-------+------------------+
2 rows in set (0.00 sec)

session2 > select * from information_schema.innodb_trx\G
Empty set (0.00 sec)

Suggested fix:
In the cases shown, 'cleaning up' state should probably be not present as it suggests that the thread may be busy doing something, which is confusing.

Interestingly, I cannot reproduce the same issue for versions 5.5.46 or 5.5.44.

Hello Przemyslaw Malkowski,

Thank you for the report and test case.
Verified as described.

Thanks,
Umesh

// 5.6.27

-- Sess 1

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.27-enterprise-commercial-advanced MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select @@version;
+---------------------------------------+
| @@version                             |
+---------------------------------------+
| 5.6.27-enterprise-commercial-advanced |
+---------------------------------------+
1 row in set (0.00 sec)

mysql> use test
Database changed
mysql> create table t1(id int not null);
Query OK, 0 rows affected (0.00 sec)

mysql> select * from test.t1;
Empty set (0.00 sec)

mysql>

-- Sess 2

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.27-enterprise-commercial-advanced MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> pager grep -A5 TRANSACTIONS
PAGER set to 'grep -A5 TRANSACTIONS'
mysql>  show engine innodb status\G
TRANSACTIONS
------------
Trx id counter 1799
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2, OS thread handle 0x7fc67987b700, query id 11 localhost root init
show engine innodb status
---TRANSACTION 1798, not started
MySQL thread id 1, OS thread handle 0x7fc6798bc700, query id 9 localhost root cleaning up
1 row in set (0.00 sec)

mysql> nopager
PAGER set to stdout
mysql> show processlist;
+----+------+-----------+------+---------+------+-------+------------------+
| Id | User | Host      | db   | Command | Time | State | Info             |
+----+------+-----------+------+---------+------+-------+------------------+
|  1 | root | localhost | test | Sleep   |   55 |       | NULL             |
|  2 | root | localhost | NULL | Query   |    0 | init  | show processlist |
+----+------+-----------+------+---------+------+-------+------------------+
2 rows in set (0.00 sec)

mysql> select * from information_schema.innodb_trx\G
Empty set (0.00 sec)

mysql>

// 5.7.10

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.10: bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.10-enterprise-commercial-advanced MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select @@version;
+---------------------------------------+
| @@version                             |
+---------------------------------------+
| 5.7.10-enterprise-commercial-advanced |
+---------------------------------------+
1 row in set (0.00 sec)

mysql> create database db1;
Query OK, 1 row affected (0.01 sec)

mysql> use db1
Database changed
mysql> create table t1(id int not null);
Query OK, 0 rows affected (0.00 sec)

mysql>  begin; select id from db1.t1 for update;
Query OK, 0 rows affected (0.00 sec)

Empty set (0.00 sec)

mysql>

-- ses 2

[umshastr@hod03]/export/umesh/server/binaries: cd mysql-advanced-5.7.10
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.10: bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.10-enterprise-commercial-advanced MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> pager grep -A5 TRANSACTIONS
PAGER set to 'grep -A5 TRANSACTIONS'
mysql> show engine innodb status\G
TRANSACTIONS
------------
Trx id counter 1288
Purge done for trx's n:o < 818 undo n:o < 0 state: running but idle
History list length 6
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421641235860192, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 1287, ACTIVE 24 sec
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 2, OS thread handle 140165741328128, query id 12 localhost root cleaning up
1 row in set (0.00 sec)

mysql> nopager
PAGER set to stdout
mysql> select * from information_schema.innodb_trx\G
*************************** 1. row ***************************
                    trx_id: 1287
                 trx_state: RUNNING
               trx_started: 2015-10-09 14:37:05
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 2
       trx_mysql_thread_id: 2
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
1 row in set (0.00 sec)

mysql> select * from information_schema.processlist;
+----+------+-----------+------+---------+------+-----------+----------------------------------------------+
| ID | USER | HOST      | DB   | COMMAND | TIME | STATE     | INFO                                         |
+----+------+-----------+------+---------+------+-----------+----------------------------------------------+
|  3 | root | localhost | NULL | Query   |    0 | executing | select * from information_schema.processlist |
|  2 | root | localhost | db1  | Sleep   |   52 |           | NULL                                         |
+----+------+-----------+------+---------+------+-----------+----------------------------------------------+
2 rows in set (0.00 sec)

mysql>

I've repeatedly seen this as well, on 5.6.17.

Killing the offending transactin works, but (single test case for the moment) then seems to break replication - is it possible that the transaction has been binlogged and shipped, yet is undone by the kill?

Posted by developer:
 
Fixed as of the upcoming 5.7.16, 5.6.34 release, and here's the changelog entry:

SHOW ENGINE INNODB STATUS output showed a cleaning up state for an idle
thread. Thread state information was not reset after statement execution.

Thank you for the bug report.

Posted by developer:
 
Changelog entry moved to 5.6.35, 5.7.17, 8.0.1 releases.