Percona Server moved to https://jira.percona.com/projects/PS

Hanging "System Lock" when executing "flush table ... for export"

Bug #1454441 reported by suanmeiguo on 2015-05-12

112

This bug affects 17 people

	Status	Importance	Assigned to	Milestone
MySQL Server	Unknown	Unknown	mysql-bugs #77011
Percona Server moved to https://jira.percona.com/projects/PS	Fix Released	High	Sergei Glushchenko	Percona Server moved to https://jira.percona.com/projects/PS 5.6.26-74.0
5.1	Invalid	Undecided	Unassigned
5.5	Invalid	Undecided	Unassigned
5.6	Fix Released	High	Sergei Glushchenko	Percona Server moved to https://jira.percona.com/projects/PS 5.6.26-74.0

Bug Description

Description:
I was trying to run "flush table ... for export" on a table. There weren't any operations on that table, the query should go through. But it didn't and the query was hanging on "System Lock" for a long time. Sometimes it hangs for minutes and sometimes it hangs for hours or days.

The environment is a busy database with a lot of DML. The table is a new table without any data, and there was no operations on it. However, there were other DML running on other tables.

We found the requirements to reproduce this issue are:
1. change buffer is actively used (ibuf_size > 1)
2. the table to be flushed has no records in change buffer (we created a new table to demonstrate this)

How to repeat:
We can now reproduce this issue in a very simple environment. So attached a link to our Vagrant file that was used to reproduce this issue.

https://github.com/ftb-dataengineering/Virtual-Machine/tree/master/system-lock

Here are 4 simple steps to reproduce the hanging system lock:

1. [terminal] vagrant up & vagrant ssh
2. [terminal] sysbench --test=/usr/share/doc/sysbench/tests/db/oltp.lua --oltp-table-size=50000000 --mysql-db=test --mysql-user=vagrant --mysql-password=vagrant prepare
3. [sql] create table app (id int primary key);
4. [sql] flush tables app for export;

Suggested fix:
We found that in percona-server/storage/innobase/ibuf/ibuf0ibuf.cc ibuf_contract_in_background function, it's stuck in the while loop. Basically the function still tries to flush the ibuf when there's no data for that specific table_id.

In this line: n_bytes = ibuf_merge(table_id, &n_pag2, FALSE);
When there's no records in change buffer for table A, it should return 0 for n_bytes, hence the loop can be broken later on. However it returns 1 instead of 0.

Eventually the issue is from ibuf_merge_space, there's a line:
++sum_sizes;

For unknown reason it plus 1, and it becomes the return value for n_bytes.

If there's purpose for ++sum_sizes, there should be a check in ibuf_contract_in_background function. Or the ++sum_sizes should be fixed.

There is a temporary solution to resolve the hanging system lock:
set global innodb_change_buffer_max_size = 0;
or
set global innodb_change_buffering = none;

This will clear the change buffer and hence break the while loop.

This bug is also report on mysql.
https://bugs.mysql.com/bug.php?id=77011

Tags:

Laurynas Biveinis (laurynas-biveinis) on 2015-05-13

tags:

added: upstream

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2015-05-25:

Download full text (6.5 KiB)

This was easy enough to verify with PS 5.6.24. While sysbench was running, I tried:

[openxs@centos ~]$ mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.24-72.2-log Percona Server (GPL), Release 72.2, Revision 8d0f85b

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> create table app(id int primary key);
Query OK, 0 rows affected (0.97 sec)

mysql> flush tables app for export;
Query OK, 0 rows affected (0.01 sec)

mysql> flush tables app for export;
ERROR 1192 (HY000): Can't execute the given command because you have active locked tables or an active transaction
mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)

mysql> flush tables app for export;
Query OK, 0 rows affected (0.00 sec)

mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)

mysql> flush tables app for export;

... and now it hanged. In other session we can see:

and, indeed, at this time change buffer is used:

This was easy enough to verify with PS 5.6.24. While sysbench was running, I tried:

[openxs@centos ~]$ mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.24-72.2-log Percona Server (GPL), Release 72.2, Revision 8d0f85b

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> create table app(id int primary key);
Query OK, 0 rows affected (0.97 sec)

mysql> flush tables app for export;
Query OK, 0 rows affected (0.01 sec)

mysql> flush tables app for export;
Query OK, 0 rows affected (0.00 sec)

mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)

mysql> flush tables app for export;

... and now it hanged. In other session we can see:

and, indeed, at this time change buffer is used:

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2015-05-25 19:50:21 7f345b658700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 37 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 166 srv_active, 0 srv_shutdown, 146 srv_idle
srv_master_thread log flush and writes: 312
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4144
--Thread 139862099334912 has waited at buf0flu.cc line 1858 for 1.0000 seconds the semaphore:
Mutex at 0x7f3457badbe8 '&buf_pool->flush_state_mutex', lock var 1
waiters flag 1
--Thread 139862848673536 has waited at buf0buf.cc line 1886 for 1.0000 seconds the semaphore:
Mutex at 0x7f3457badaa8 '&buf_pool->LRU_list_mutex', lock var 1
waiters flag 1
OS WAIT ARRAY INFO: signal count 3827
Mutex spin waits 1340, rounds 40736, OS waits 1137
RW-shared spins 1759, rounds 54488, OS waits 760
RW-excl spins 200, rounds 67536, OS waits 2164
Spin rounds per wait: 30.40 mutex, 30.98 RW-shared, 337.68 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 123819
Purge done for trx's n:o < 123752 undo n:o < 0 state: stopped
History list length 215
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 3, OS thread handle 0x7f345b658700, query id 138 localhost root init
show engine innodb status
---TRANSACTION 0, not started
MySQL thread id 1, OS thread handle 0x7f345b6da700, query id 81 localhost root System lock
flush tables app for export
---TRANSACTION 123818, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1081
MySQL thread id 2, OS thread handle 0x7f345b699700, query id 137 localhost root update
INSERT INTO sbtest1(k, c, pad) VALUES(2520188, '23265171360-40256758300-76422825425-13580470856-20610876655-51059683997-20531291710-60899682120-24328394273-84119137420', '53620872615-59974842661-44683850061-54412224416-74849613198'),(2476861, '86696909084-02479793694-51170576190-45122155285-89858238887-68479987794-32082721316-60674682103-56050409979-52868593074', '09988394520-20659103006-21980839252-20858888383-30008858837'),(2488714, '66342712639-57030167917-87404020530-99067237210-80875833843-84157380906-03751940334-97032191790-84280038367-03049564210', '79326798778-33162785414-08336700839-4
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: complete io for buf page (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 1
2565 OS file reads, 11860 OS file writes, 1368 OS fsyncs
11.81 reads/s, 16384 avg bytes/read, 74.11 writes/s, 8.19 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 6, free list len 99, seg size 106, 1109 merges
merged operations:
 insert 21452, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
843.33 hash searches/s, 53876.54 non-hash searches/s
...

see "size 6" above.

Valerii Kravchuk (valerii-kravchuk) on 2015-07-15

tags:

added: i56733

Revision history for this message

Sergei Glushchenko (sergei.glushchenko) wrote on 2015-07-27:

https://github.com/percona/percona-server/pull/121

Revision history for this message

Roel Van de Paar (roel11) wrote on 2015-08-04:

This bug looks upstream-familiar (besides 77011). If still needed, I can go and find/check. Let me know.

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-25:

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-900

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

mysql-bugs #77011 Edit

Bug watches keep track of this bug in other bug trackers.