Bug #73829 Multi-threaded mysqld lockup issue with ~50-55 second timeout
Submitted: 8 Sep 2014 5:06 Modified: 31 Dec 2014 7:49
Reporter: Roel Van de Paar (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Locking Severity:S1 (Critical)
Version:5.6, 5.6.21, 5.6.23, 5.7.6 OS:Any
Assigned to: CPU Architecture:Any

[8 Sep 2014 5:06] Roel Van de Paar
Description:
Multi-threaded mysqld lockup issue with ~50-55 second timeout (simultaneous states "updating/"Waiting for table metadata lock"/"Waiting for table flush"). Some connections run/lockup more then 55 seconds, depending on the situation (random testing reveals different results).

How to repeat:
Testcase:

1. Branch lp:percona-qa and cd pquery
2. Startup mysqld (I used Percona-Server-5.6.20-rel68.0-654.Linux.x86_64-debug)
3. Execute:
    export LD_LIBRARY_PATH=/sda/mysql-5.6.20-linux-glibc2.5-x86_64/lib/
    ./pquery --infile=./out.2 --database=test --threads=100 --verbose --user=root --socket=/sda/mysql-5.6.20-linux-glibc2.5-x86_64/socket.sock
4. Connect with mysql cli client and repeat SHOW PROCESSLIST;
5. Wait a while till lockup starts appearing. It will look like this (I've removed a few redundant columns to make paste clearer):

mysql> show processlist;
+------+---------+------+---------------------------------+----------------------------------------+
| Id | Command | Time | State | Info |
+------+---------+------+---------------------------------+----------------------------------------+
| 1238 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1239 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1240 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1241 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1242 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1243 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1244 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1245 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1246 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1247 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1248 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1249 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1250 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1251 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1252 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1253 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1254 | Query | 47 | updating | DELETE FROM t2 LIMIT 1 |
| 1255 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1256 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1257 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1258 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1259 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1260 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1261 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1262 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1263 | Query | 46 | Waiting for table flush | FLUSH TABLES |
| 1264 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1265 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1266 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1267 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1268 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1269 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1270 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1271 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1272 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1273 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1274 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1275 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1276 | Query | 46 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1277 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1278 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1279 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1280 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1281 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1282 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1283 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1284 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1285 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1286 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1287 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1288 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1289 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1290 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1291 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1292 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1293 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1294 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1295 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1296 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1297 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1298 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1299 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1300 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1301 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1302 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1303 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1304 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1305 | Query | 47 | Waiting for table flush | INSERT INTO t2 VALUES (1,2,3) |
| 1306 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1307 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1308 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1309 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1310 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1311 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1312 | Query | 47 | updating | DELETE FROM t2 LIMIT 1 |
| 1313 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1314 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1315 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1316 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1317 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1318 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1319 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1320 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1321 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1322 | Query | 47 | updating | DELETE FROM t2 LIMIT 1 |
| 1323 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1324 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1325 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1326 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1327 | Query | 47 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1328 | Query | 47 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1329 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1330 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1331 | Query | 47 | updating | DELETE FROM t2 LIMIT 1 |
| 1332 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1333 | Query | 47 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1334 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1335 | Query | 47 | Waiting for table flush | FLUSH TABLES |
| 1336 | Query | 47 | Waiting for table metadata lock | DROP TABLE t2 |
| 1337 | Query | 47 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1338 | Query | 0 | init | show processlist |
+------+---------+------+---------------------------------+----------------------------------------+
101 rows in set (0.00 sec)

And, after some sort of (hardcoded?) 50-53 second timeout is hit (the threads with 0-1 second time are fresh commands - they are not relevant):

mysql> show processlist;
+------+---------+------+---------------------------------+----------------------------------------+
| Id | Command | Time | State | Info |
+------+---------+------+---------------------------------+----------------------------------------+
| 1238 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1239 | Query | 0 | Waiting for table metadata lock | DELETE FROM t1 LIMIT 1 |
| 1240 | Query | 0 | Waiting for table metadata lock | INSERT INTO t1 VALUES (1,2,3) |
| 1241 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1242 | Query | 1 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1243 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1244 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1245 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1246 | Query | 1 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1247 | Query | 0 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1248 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1249 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1250 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1251 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1252 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1253 | Query | 0 | Waiting for table metadata lock | DROP TABLE t1 |
| 1254 | Query | 1 | creating table | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1255 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1256 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1257 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1258 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1259 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t1 |
| 1260 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1261 | Query | 0 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1262 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1263 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t1 |
| 1264 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t1 |
| 1265 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1266 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1267 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1268 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1269 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1270 | Query | 0 | Waiting for table metadata lock | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1271 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1272 | Query | 0 | init | COMMIT |
| 1273 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1274 | Query | 1 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1275 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1276 | Query | 51 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1277 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1278 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1279 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1280 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1281 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1282 | Query | 0 | Waiting for table metadata lock | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1283 | Query | 1 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1284 | Query | 0 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1285 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1286 | Query | 0 | Waiting for table metadata lock | INSERT INTO t1 VALUES (1,2,3) |
| 1287 | Query | 0 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1288 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1289 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1290 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1291 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1292 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1293 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1294 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1295 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1296 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1297 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1298 | Query | 0 | closing tables | DROP TABLE t2 |
| 1299 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1300 | Query | 0 | Waiting for table metadata lock | CREATE TABLE t1 (c1 INT,c2 INT,c3 INT) |
| 1301 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1302 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1303 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1304 | Query | 0 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1305 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t1 |
| 1306 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t1 |
| 1307 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1308 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1309 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1310 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1311 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1312 | Query | 0 | Waiting for table metadata lock | DROP TABLE t1 |
| 1313 | Query | 0 | Waiting for table metadata lock | DELETE FROM t1 LIMIT 1 |
| 1314 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1315 | Query | 1 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1316 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1317 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1318 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1319 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1320 | Query | 1 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1321 | Query | 0 | Waiting for table metadata lock | SELECT c1 FROM t1 |
| 1322 | Query | 1 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1323 | Query | 0 | Waiting for table metadata lock | DROP TABLE t1 |
| 1324 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1325 | Query | 1 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1326 | Query | 0 | Waiting for table metadata lock | DROP TABLE t2 |
| 1327 | Query | 52 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1328 | Query | 52 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1329 | Query | 0 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1330 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1331 | Query | 1 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1332 | Query | 0 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1333 | Query | 52 | Waiting for table metadata lock | CREATE TABLE t2 (c1 INT,c2 INT,c3 INT) |
| 1334 | Query | 0 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1335 | Query | 0 | Waiting for table metadata lock | INSERT INTO t2 VALUES (1,2,3) |
| 1336 | Query | 1 | Waiting for table metadata lock | SELECT c1 FROM t2 |
| 1337 | Query | 52 | Waiting for table metadata lock | DELETE FROM t2 LIMIT 1 |
| 1338 | Query | 0 | init | show processlist |
+------+---------+------+---------------------------------+----------------------------------------+
101 rows in set (0.00 sec)

The lockup issue is consistently repeatable, and it's always around 50-55 seconds that the state "resets", though as mentioned above at times threads keep running past 55 seconds while others have already reset around the 50-55 seconds time.

Suggested fix:
No lockups.
[8 Sep 2014 5:11] Roel Van de Paar
pquery-ms, sql file, run-ms file (full testcase, avoids need to branch percona_qa)

Attachment: bug_73829.tar.gz (application/gzip, text), 69.89 KiB.

[8 Sep 2014 5:12] Roel Van de Paar
For completeness, my mysqld start and client script. jemalloc part can likely be ignored.

[roel@localhost mysql-5.6.20-linux-glibc2.5-x86_64]$ cat start
if [ -r /usr/lib64/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib64/libjemalloc.so.1
elif [ -r /usr/lib/x86_64-linux-gnu/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
elif [ -r /sda/mysql-5.6.20-linux-glibc2.5-x86_64/lib/mysql/libjemalloc.so.1 ]; then export LD_PRELOAD=/sda/mysql-5.6.20-linux-glibc2.5-x86_64/lib/mysql/libjema
lloc.so.1
else echo 'Error: jemalloc not found, please install it first'; exit 1; fi
/sda/mysql-5.6.20-linux-glibc2.5-x86_64/bin/mysqld --innodb_buffer_pool_size=2147483648 --basedir=/sda/mysql-5.6.20-linux-glibc2.5-x86_64 --datadir=/sda/mysql-5
.6.20-linux-glibc2.5-x86_64/data --core --socket=/sda/mysql-5.6.20-linux-glibc2.5-x86_64/socket.sock --port=10920 --log-error=/sda/mysql-5.6.20-linux-glibc2.5-x
86_64/log/master.err 2>&1 &
echo 'Server socket: /sda/mysql-5.6.20-linux-glibc2.5-x86_64/socket.sock with datadir: /sda/mysql-5.6.20-linux-glibc2.5-x86_64/data'

[roel@localhost mysql-5.6.20-linux-glibc2.5-x86_64]$ cat cl
/sda/mysql-5.6.20-linux-glibc2.5-x86_64/bin/mysql -A -uroot -S/sda/mysql-5.6.20-linux-glibc2.5-x86_64/socket.sock test
[8 Sep 2014 7:56] Shane Bester
could this be innodb_lock_wait_timeout that you're hitting ?  AFAIK all threads waiting for lock are checked by the background timeout thread once per second (approximately).
[8 Sep 2014 8:43] Roel Van de Paar
Yes! That must be it - the default setting is 50. Thanks. So that explains the 50 second timeout being hit, but as for the lockup situation itself, it seems to give more interesting questions;
1. Why does a very simple query/trx with LIMIT 1 for example lock the other threads for 50+ seconds?
2. Why do some threads run way past 50 - unless it is a double lockup in some cases?
3. (Minor) considering the per-second check you're mentioning, why do some threads run up to 55 while - with only ~100 connections and simple queries/trx - it should only take a split second to process/timeout?
[6 Oct 2014 22:59] Roel Van de Paar
Umesh, any updates?
[7 Oct 2014 5:01] Shane Bester
I'm guessing information in information_schema.innodb_trx, information_schema.inodb_locks, information_schema.innodb_lock_waits would help narrow down things.
[11 Nov 2014 21:44] Roel Van de Paar
Umesh, testcase for this bug should make it easy to repeat. Any updates?
[13 Nov 2014 7:36] Umesh Shastry
Hello Roel,

Thank you for the bug report and test case.
Observed similar behavior on 5.6.21 with the provided test case.

Thank,
Umesh
[13 Nov 2014 7:37] Umesh Shastry
pquery-ms requires >=`GLIBC_2.14`
[13 Nov 2014 19:56] Roel Van de Paar
Umesh, 5.7 does not show it?
[14 Nov 2014 4:17] Umesh Shastry
Hi Roel, 

I Would check it on later today and update.

Thanks,
Umesh
[20 Nov 2014 22:08] Roel Van de Paar
Another example of what can be seen

Attachment: 55sec bug.txt (text/plain), 138.07 KiB.

[10 Dec 2014 13:20] Umesh Shastry
test results

Attachment: 73829.txt (text/plain), 29.97 KiB.

[31 Dec 2014 7:49] Roel Van de Paar
Any updates?
[26 Feb 2015 6:13] Shane Bester
maybe devs can check if this is the cause:
http://bugs.mysql.com/bug.php?id=72123