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

Comment 1 for bug 1466414

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2015-06-24:

This is easy to confirm on 5.6 as well (I've added query_veritval SHGOW ENGINE INNODB STATUS; to the MTR test case):

...
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1466414 [ fail ]
Test ended at 2015-06-24 11:03:56

CURRENT_TEST: main.1466414
--- /home/openxs/dbs/p5.6/mysql-test/r/1466414.result 2015-06-24 11:00:55.227564574 +0300
+++ /home/openxs/dbs/p5.6/mysql-test/var/log/1466414.reject 2015-06-24 11:03:56.178302839 +0300
@@ -0,0 +1,160 @@
+create table t(a INT PRIMARY KEY, b INT) engine=InnoDB;
+insert into t values(2,1);
+insert into t values(1,2);
+SET GLOBAL innodb_monitor_reset=lock_deadlocks;
+BEGIN;
+SELECT b FROM t WHERE a=1 FOR UPDATE;
+b
+2
+BEGIN;
+SELECT b FROM t WHERE a=2 FOR UPDATE;
+b
+1
+SELECT b FROM t WHERE a=2 FOR UPDATE;
+SELECT b FROM t WHERE a=1 FOR UPDATE;
+b
+1
+ROLLBACK;
+ROLLBACK;
+SHOW ENGINE INNODB STATUS;
+Type InnoDB
+Name
+Status
+=====================================
+2015-06-24 11:03:56 7f35a856e700 INNODB MONITOR OUTPUT
+=====================================
+Per second averages calculated from the last 1 seconds
+-----------------
+BACKGROUND THREAD
+-----------------
+srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 0 srv_idle
+srv_master_thread log flush and writes: 0
+----------
+SEMAPHORES
+----------
+OS WAIT ARRAY INFO: reservation count 4
+OS WAIT ARRAY INFO: signal count 4
+Mutex spin waits 2, rounds 60, OS waits 2
+RW-shared spins 2, rounds 60, OS waits 2
+RW-excl spins 0, rounds 0, OS waits 0
+Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
+------------------------
+LATEST DETECTED DEADLOCK
+------------------------
+2015-06-24 11:03:56 7f35a84ec700
+*** (1) TRANSACTION:
+TRANSACTION 1293, ACTIVE 0 sec starting index read
+mysql tables in use 1, locked 1
+LOCK WAIT 3 lock struct(s), heap size 360, 2 row lock(s)
+MySQL thread id 3, OS thread handle 0x7f35a852d700, query id 33 localhost root statistics
+SELECT b FROM t WHERE a=2 FOR UPDATE
+*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1293 lock_mode X locks rec but not gap waiting
+*** (2) TRANSACTION:
+TRANSACTION 1294, ACTIVE 0 sec starting index read
+mysql tables in use 1, locked 1
+3 lock struct(s), heap size 360, 2 row lock(s)
+MySQL thread id 4, OS thread handle 0x7f35a84ec700, query id 34 localhost root statistics
+SELECT b FROM t WHERE a=1 FOR UPDATE
+*** (2) HOLDS THE LOCK(S):
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1294 lock_mode X locks rec but not gap
+*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1294 lock_mode X locks rec but not gap waiting
+*** WE ROLL BACK TRANSACTION (2)
+------------
+TRANSACTIONS
+------------
+Trx id counter 1297
+Purge done for trx's n:o < 1297 undo n:o < 0 state: running but idle
+History list length 2
+LIST OF TRANSACTIONS FOR EACH SESSION:
+---TRANSACTION 0, not started
+MySQL thread id 2, OS thread handle 0x7f35a856e700, query id 37 localhost root init
+SHOW ENGINE INNODB STATUS
+---TRANSACTION 1293, not started
+MySQL thread id 3, OS thread handle 0x7f35a852d700, query id 35 localhost root cleaning up
+---TRANSACTION 1294, not started
+MySQL thread id 4, OS thread handle 0x7f35a84ec700, query id 36 localhost root cleaning up
+--------
+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 (write thread)
+I/O thread 5 state: waiting for completed aio requests (write thread)
+Pending normal aio reads: 0 [0, 0] , aio writes: 0 [0, 0] ,
+ ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
+Pending flushes (fsync) log: 0; buffer pool: 0
+181 OS file reads, 11 OS file writes, 11 OS fsyncs
+26.97 reads/s, 16384 avg bytes/read, 9.99 writes/s, 9.99 fsyncs/s
+-------------------------------------
+INSERT BUFFER AND ADAPTIVE HASH INDEX
+-------------------------------------
+Ibuf: size 1, free list len 0, seg size 2, 0 merges
+merged operations:
+ insert 0, delete mark 0, delete 0
+discarded operations:
+ insert 0, delete mark 0, delete 0
+0.00 hash searches/s, 94.91 non-hash searches/s
+---
+LOG
+---
+Log sequence number 1634963
+Log flushed up to 1634963
+Pages flushed up to 1625977
+Last checkpoint at 1625977
+Max checkpoint age 7782360
+Checkpoint age target 7539162
+Modified age 8986
+Checkpoint age 8986
+0 pending log writes, 0 pending chkp writes
+13 log i/o's done, 7.00 log i/o's/second
+----------------------
+BUFFER POOL AND MEMORY
+----------------------
+Total memory allocated 8585216; in additional pool allocated 0
+Total memory allocated by read views 104
+Internal hash tables (constant factor + variable factor)
+ Adaptive hash index 143072 (138872 + 4200)
+ Page hash 9208 (buffer pool 0 only)
+ Dictionary cache 100460 (36272 + 64188)
+ File system 816376 (812272 + 4104)
+ Lock system 22672 (21592 + 1080)
+ Recovery system 0 (0 + 0)
+Dictionary memory allocated 64188
+Buffer pool size 511
+Buffer pool size, bytes 8372224
+Free buffers 337
+Database pages 174
+Old database pages 0
+Modified db pages 29
+Pending reads 0
+Pending writes: LRU 0, flush list 0, single page 0
+Pages made young 0, not young 0
+0.00 youngs/s, 0.00 non-youngs/s
+Pages read 165, created 9, written 0
+21.98 reads/s, 8.99 creates/s, 0.00 writes/s
+Buffer pool hit rate 956 / 1000, young-making rate 0 / 1000 not 0 / 1000
+Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
+LRU len: 174, unzip_LRU len: 0
+I/O sum[0]:cur[22], unzip sum[0]:cur[0]
+--------------
+ROW OPERATIONS
+--------------
+0 queries inside InnoDB, 0 queries in queue
+0 read views open inside InnoDB
+0 RW transactions active inside InnoDB
+0 RO transactions active inside InnoDB
+0 out of 1000 descriptors used
+Main thread process no. 2661, id 139868336277248, state: sleeping
+Number of rows inserted 2, updated 0, deleted 0, read 3
+2.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3.00 reads/s
+----------------------------
+END OF INNODB MONITOR OUTPUT
+============================
+
+SELECT NAME, COUNT, COMMENT FROM INFORMATION_SCHEMA.INNODB_METRICS WHERE NAME="lock_deadlocks";
+NAME COUNT COMMENT
+lock_deadlocks 0 Number of deadlocks

mysqltest: Result length mismatch

- saving '/home/openxs/dbs/p5.6/mysql-test/var/log/main.1466414/' to '/home/openxs/dbs/p5.6/mysql-test/var/log/main.1466414/'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 9 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.1466414

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

This is easy to confirm on 5.6 as well (I've added query_veritval SHGOW ENGINE INNODB STATUS; to the MTR test case):

...
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1466414                             [ fail ]
        Test ended at 2015-06-24 11:03:56

CURRENT_TEST: main.1466414
--- /home/openxs/dbs/p5.6/mysql-test/r/1466414.result   2015-06-24 11:00:55.227564574 +0300
+++ /home/openxs/dbs/p5.6/mysql-test/var/log/1466414.reject     2015-06-24 11:03:56.178302839 +0300
@@ -0,0 +1,160 @@
+create table t(a INT PRIMARY KEY, b INT) engine=InnoDB;
+insert into t values(2,1);
+insert into t values(1,2);
+SET GLOBAL innodb_monitor_reset=lock_deadlocks;
+BEGIN;
+SELECT b FROM t WHERE a=1 FOR UPDATE;
+b
+2
+BEGIN;
+SELECT b FROM t WHERE a=2 FOR UPDATE;
+b
+1
+SELECT b FROM t WHERE a=2 FOR UPDATE;
+SELECT b FROM t WHERE a=1 FOR UPDATE;
+b
+1
+ROLLBACK;
+ROLLBACK;
+SHOW ENGINE INNODB STATUS;
+Type   InnoDB
+Name
+Status
+=====================================
+2015-06-24 11:03:56 7f35a856e700 INNODB MONITOR OUTPUT
+=====================================
+Per second averages calculated from the last 1 seconds
+-----------------
+BACKGROUND THREAD
+-----------------
+srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 0 srv_idle
+srv_master_thread log flush and writes: 0
+----------
+SEMAPHORES
+----------
+OS WAIT ARRAY INFO: reservation count 4
+OS WAIT ARRAY INFO: signal count 4
+Mutex spin waits 2, rounds 60, OS waits 2
+RW-shared spins 2, rounds 60, OS waits 2
+RW-excl spins 0, rounds 0, OS waits 0
+Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
+------------------------
+LATEST DETECTED DEADLOCK
+------------------------
+2015-06-24 11:03:56 7f35a84ec700
+*** (1) TRANSACTION:
+TRANSACTION 1293, ACTIVE 0 sec starting index read
+mysql tables in use 1, locked 1
+LOCK WAIT 3 lock struct(s), heap size 360, 2 row lock(s)
+MySQL thread id 3, OS thread handle 0x7f35a852d700, query id 33 localhost root statistics
+SELECT b FROM t WHERE a=2 FOR UPDATE
+*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1293 lock_mode X locks rec but not gap waiting
+*** (2) TRANSACTION:
+TRANSACTION 1294, ACTIVE 0 sec starting index read
+mysql tables in use 1, locked 1
+3 lock struct(s), heap size 360, 2 row lock(s)
+MySQL thread id 4, OS thread handle 0x7f35a84ec700, query id 34 localhost root statistics
+SELECT b FROM t WHERE a=1 FOR UPDATE
+*** (2) HOLDS THE LOCK(S):
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1294 lock_mode X locks rec but not gap
+*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1294 lock_mode X locks rec but not gap waiting
+*** WE ROLL BACK TRANSACTION (2)
+------------
+TRANSACTIONS
+------------
+Trx id counter 1297
+Purge done for trx's n:o < 1297 undo n:o < 0 state: running but idle
+History list length 2
+LIST OF TRANSACTIONS FOR EACH SESSION:
+---TRANSACTION 0, not started
+MySQL thread id 2, OS thread handle 0x7f35a856e700, query id 37 localhost root init
+SHOW ENGINE INNODB STATUS
+---TRANSACTION 1293, not started
+MySQL thread id 3, OS thread handle 0x7f35a852d700, query id 35 localhost root cleaning up
+---TRANSACTION 1294, not started
+MySQL thread id 4, OS thread handle 0x7f35a84ec700, query id 36 localhost root cleaning up
+--------
+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 (write thread)
+I/O thread 5 state: waiting for completed aio requests (write thread)
+Pending normal aio reads: 0 [0, 0] , aio writes: 0 [0, 0] ,
+ ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
+Pending flushes (fsync) log: 0; buffer pool: 0
+181 OS file reads, 11 OS file writes, 11 OS fsyncs
+26.97 reads/s, 16384 avg bytes/read, 9.99 writes/s, 9.99 fsyncs/s
+-------------------------------------
+INSERT BUFFER AND ADAPTIVE HASH INDEX
+-------------------------------------
+Ibuf: size 1, free list len 0, seg size 2, 0 merges
+merged operations:
+ insert 0, delete mark 0, delete 0
+discarded operations:
+ insert 0, delete mark 0, delete 0
+0.00 hash searches/s, 94.91 non-hash searches/s
+---
+LOG
+---
+Log sequence number 1634963
+Log flushed up to   1634963
+Pages flushed up to 1625977
+Last checkpoint at  1625977
+Max checkpoint age    7782360
+Checkpoint age target 7539162
+Modified age          8986
+Checkpoint age        8986
+0 pending log writes, 0 pending chkp writes
+13 log i/o's done, 7.00 log i/o's/second
+----------------------
+BUFFER POOL AND MEMORY
+----------------------
+Total memory allocated 8585216; in additional pool allocated 0
+Total memory allocated by read views 104
+Internal hash tables (constant factor + variable factor)
+    Adaptive hash index 143072         (138872 + 4200)
+    Page hash           9208 (buffer pool 0 only)
+    Dictionary cache    100460         (36272 + 64188)
+    File system         816376         (812272 + 4104)
+    Lock system         22672  (21592 + 1080)
+    Recovery system     0      (0 + 0)
+Dictionary memory allocated 64188
+Buffer pool size        511
+Buffer pool size, bytes 8372224
+Free buffers            337
+Database pages          174
+Old database pages      0
+Modified db pages       29
+Pending reads 0
+Pending writes: LRU 0, flush list 0, single page 0
+Pages made young 0, not young 0
+0.00 youngs/s, 0.00 non-youngs/s
+Pages read 165, created 9, written 0
+21.98 reads/s, 8.99 creates/s, 0.00 writes/s
+Buffer pool hit rate 956 / 1000, young-making rate 0 / 1000 not 0 / 1000
+Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
+LRU len: 174, unzip_LRU len: 0
+I/O sum[0]:cur[22], unzip sum[0]:cur[0]
+--------------
+ROW OPERATIONS
+--------------
+0 queries inside InnoDB, 0 queries in queue
+0 read views open inside InnoDB
+0 RW transactions active inside InnoDB
+0 RO transactions active inside InnoDB
+0 out of 1000 descriptors used
+Main thread process no. 2661, id 139868336277248, state: sleeping
+Number of rows inserted 2, updated 0, deleted 0, read 3
+2.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3.00 reads/s
+----------------------------
+END OF INNODB MONITOR OUTPUT
+============================
+
+SELECT NAME, COUNT, COMMENT FROM INFORMATION_SCHEMA.INNODB_METRICS WHERE NAME="lock_deadlocks";
+NAME   COUNT   COMMENT
+lock_deadlocks 0       Number of deadlocks

mysqltest: Result length mismatch

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.1466414

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases