[MDEV-11342] OQGRAPH should acquire meta-data locks on "backing" tables - Jira

Details

Type: Bug
Status: Open (View Workflow)
Priority: Minor
Resolution: Unresolved
Affects Version/s: 10.1.19, 10.2.2, 10.1(EOL), 10.2(EOL)
Fix Version/s: 10.4(EOL)
Component/s: Storage Engine - InnoDB, Storage Engine - OQGRAPH
Labels:
- foundation
Environment:
Centos 7 with MariaDB built RPM's

Description

After attempting to upgrade Mariadb from 10.0.x to 10.1.x we ran into a "drop database" issue that was not present in 10.0.x. The issue is reproducible at will. If a database has an Innodb table that has an OQGRAPH table referencing it and you drop the entire database, Innodb goes into a meltdown.

Test case on empty database: create an empty table and then an OQGRAPH table referencing it:

CREATE TABLE `routes` (

  `orig_node_id` int(10) unsigned NOT NULL,

  `dest_node_id` int(10) unsigned NOT NULL,

  `weight` double NOT NULL,

  PRIMARY KEY (`orig_node_id`,`dest_node_id`),

  KEY `dest_node_id` (`dest_node_id`)

) ENGINE=InnoDB;

CREATE TABLE `routing` (

  `latch` varchar(32) DEFAULT NULL,

  `origid` bigint(20) unsigned DEFAULT NULL,

  `destid` bigint(20) unsigned DEFAULT NULL,

  `weight` double DEFAULT NULL,

  `seq` bigint(20) unsigned DEFAULT NULL,

  `linkid` bigint(20) unsigned DEFAULT NULL,

  KEY `latch` (`latch`,`origid`,`destid`) USING HASH,

  KEY `latch_2` (`latch`,`destid`,`origid`) USING HASH

) ENGINE=OQGRAPH `data_table`='routes' `origid`='orig_node_id' `destid`='dest_node_id' `weight`='weight';

Then do below and watch the MariaDB logs:

echo "drop database test" | mysql

Nov 23 22:55:20 ip-30-7-0-23 mysqld: 2016-11-23 22:55:20 139686369522432 [Warning] InnoDB: Waited 30 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:55:50 ip-30-7-0-23 mysqld: 2016-11-23 22:55:50 139686369522432 [Warning] InnoDB: Waited 60 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:56:20 ip-30-7-0-23 mysqld: 2016-11-23 22:56:20 139686369522432 [Warning] InnoDB: Waited 90 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:56:50 ip-30-7-0-23 mysqld: 2016-11-23 22:56:50 139686369522432 [Warning] InnoDB: Waited 120 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:57:20 ip-30-7-0-23 mysqld: 2016-11-23 22:57:20 139686369522432 [Warning] InnoDB: Waited 150 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:57:50 ip-30-7-0-23 mysqld: 2016-11-23 22:57:50 139686369522432 [Warning] InnoDB: Waited 180 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:58:20 ip-30-7-0-23 mysqld: 2016-11-23 22:58:20 139686369522432 [Warning] InnoDB: Waited 210 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:58:50 ip-30-7-0-23 mysqld: 2016-11-23 22:58:50 139686369522432 [Warning] InnoDB: Waited 240 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:58:51 ip-30-7-0-23 mysqld: 2016-11-23 22:58:51 139685468825344 [Warning] InnoDB: A long semaphore wait:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 241.00 seconds the semaphore:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:58:51 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:58:51 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:58:51 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:58:51 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:58:51 ip-30-7-0-23 mysqld: 2016-11-23 22:58:51 139685468825344 [Note] InnoDB: A semaphore wait:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 241.00 seconds the semaphore:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:58:51 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:58:51 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:58:51 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:58:51 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:58:51 ip-30-7-0-23 mysqld: 2016-11-23 22:58:51 139685468825344 [Note] InnoDB: A semaphore wait:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: --Thread 139685452039936 has waited at srv0srv.cc line 2243 for 240.00 seconds the semaphore:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: X-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:58:51 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:58:51 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:58:51 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:58:51 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:58:51 ip-30-7-0-23 mysqld: InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

Nov 23 22:58:51 ip-30-7-0-23 mysqld: InnoDB: Pending preads 0, pwrites 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: =====================================

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 2016-11-23 22:58:53 0x7f0b0e3fd700 INNODB MONITOR OUTPUT

Nov 23 22:58:53 ip-30-7-0-23 mysqld: =====================================

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Per second averages calculated from the last 8 seconds

Nov 23 22:58:53 ip-30-7-0-23 mysqld: -----------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: BACKGROUND THREAD

Nov 23 22:58:53 ip-30-7-0-23 mysqld: -----------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 496 srv_idle

Nov 23 22:58:53 ip-30-7-0-23 mysqld: srv_master_thread log flush and writes: 497

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ----------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: SEMAPHORES

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ----------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: OS WAIT ARRAY INFO: reservation count 6

Nov 23 22:58:53 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 243.00 seconds the semaphore:

Nov 23 22:58:53 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:58:53 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:58:53 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:58:53 ip-30-7-0-23 mysqld: --Thread 139685452039936 has waited at srv0srv.cc line 2243 for 242.00 seconds the semaphore:

Nov 23 22:58:53 ip-30-7-0-23 mysqld: X-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:58:53 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:58:53 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:58:53 ip-30-7-0-23 mysqld: OS WAIT ARRAY INFO: signal count 4

Nov 23 22:58:53 ip-30-7-0-23 mysqld: RW-shared spins 0, rounds 8, OS waits 4

Nov 23 22:58:53 ip-30-7-0-23 mysqld: RW-excl spins 0, rounds 0, OS waits 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: RW-sx spins 0, rounds 0, OS waits 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Spin rounds per wait: 8.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: TRANSACTIONS

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Trx id counter 8974

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Purge done for trx's n:o < 8972 undo n:o < 0 state: running

Nov 23 22:58:53 ip-30-7-0-23 mysqld: History list length 81

Nov 23 22:58:53 ip-30-7-0-23 mysqld: LIST OF TRANSACTIONS FOR EACH SESSION:

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ---TRANSACTION 421161104051016, not started

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ---TRANSACTION 421161104050056, not started

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ---TRANSACTION 8969, ACTIVE 243 sec dropping table

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: MySQL thread id 7, OS thread handle 0x7f0b446f7300, query id 118 localhost root Unlocking tables

Nov 23 22:58:53 ip-30-7-0-23 mysqld: drop database axon

Nov 23 22:58:53 ip-30-7-0-23 mysqld: --------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: FILE I/O

Nov 23 22:58:53 ip-30-7-0-23 mysqld: --------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 0 state: waiting for completed aio requests (insert buffer thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 1 state: waiting for completed aio requests (log thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 2 state: waiting for completed aio requests (read thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 3 state: waiting for completed aio requests (read thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 4 state: waiting for completed aio requests (read thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 5 state: waiting for completed aio requests (read thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 6 state: waiting for completed aio requests (write thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 7 state: waiting for completed aio requests (write thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 8 state: waiting for completed aio requests (write thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O thread 9 state: waiting for completed aio requests (write thread)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ibuf aio reads:, log i/o's:, sync i/o's:

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pending flushes (fsync) log: 0; buffer pool: 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 313 OS file reads, 95 OS file writes, 30 OS fsyncs

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: -------------------------------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: INSERT BUFFER AND ADAPTIVE HASH INDEX

Nov 23 22:58:53 ip-30-7-0-23 mysqld: -------------------------------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Ibuf: size 1, free list len 0, seg size 2, 0 merges

Nov 23 22:58:53 ip-30-7-0-23 mysqld: merged operations:

Nov 23 22:58:53 ip-30-7-0-23 mysqld: insert 0, delete mark 0, delete 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: discarded operations:

Nov 23 22:58:53 ip-30-7-0-23 mysqld: insert 0, delete mark 0, delete 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 1 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 1 buffer(s)

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0.00 hash searches/s, 0.00 non-hash searches/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ---

Nov 23 22:58:53 ip-30-7-0-23 mysqld: LOG

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ---

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Log sequence number 1759389

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Log flushed up to   1759389

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pages flushed up to 1759389

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Last checkpoint at  1757801

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0 pending log flushes, 0 pending chkp writes

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 20 log i/o's done, 0.00 log i/o's/second

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ----------------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: BUFFER POOL AND MEMORY

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ----------------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Total large memory allocated 138215424

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Dictionary memory allocated 251473

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Buffer pool size   8192

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Free buffers       7867

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Database pages     323

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Old database pages 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Modified db pages  0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Percent of dirty pages(LRU & free pages): 0.000

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Max dirty pages percent: 75.000

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pending reads 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pending writes: LRU 0, flush list 0, single page 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pages made young 0, not young 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0.00 youngs/s, 0.00 non-youngs/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pages read 284, created 39, written 62

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0.00 reads/s, 0.00 creates/s, 0.00 writes/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: No buffer pool page gets since the last printout

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: LRU len: 323, unzip_LRU len: 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: I/O sum[0]:cur[0], unzip sum[0]:cur[0]

Nov 23 22:58:53 ip-30-7-0-23 mysqld: --------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ROW OPERATIONS

Nov 23 22:58:53 ip-30-7-0-23 mysqld: --------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0 queries inside InnoDB, 0 queries in queue

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0 read views open inside InnoDB

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Process ID=4049, Main thread ID=139685452039936, state: enforcing dict cache limit

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Number of rows inserted 0, updated 0, deleted 0, read 259

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: Number of system rows inserted 0, updated 0, deleted 0, read 0

Nov 23 22:58:53 ip-30-7-0-23 mysqld: 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ----------------------------

Nov 23 22:58:53 ip-30-7-0-23 mysqld: END OF INNODB MONITOR OUTPUT

Nov 23 22:58:53 ip-30-7-0-23 mysqld: ============================

Nov 23 22:59:13 ip-30-7-0-23 mysqld: =====================================

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 2016-11-23 22:59:13 0x7f0b0e3fd700 INNODB MONITOR OUTPUT

Nov 23 22:59:13 ip-30-7-0-23 mysqld: =====================================

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Per second averages calculated from the last 20 seconds

Nov 23 22:59:13 ip-30-7-0-23 mysqld: -----------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: BACKGROUND THREAD

Nov 23 22:59:13 ip-30-7-0-23 mysqld: -----------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 496 srv_idle

Nov 23 22:59:13 ip-30-7-0-23 mysqld: srv_master_thread log flush and writes: 497

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ----------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: SEMAPHORES

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ----------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: OS WAIT ARRAY INFO: reservation count 6

Nov 23 22:59:13 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 263.00 seconds the semaphore:

Nov 23 22:59:13 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:13 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:13 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:13 ip-30-7-0-23 mysqld: --Thread 139685452039936 has waited at srv0srv.cc line 2243 for 262.00 seconds the semaphore:

Nov 23 22:59:13 ip-30-7-0-23 mysqld: X-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:13 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:13 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:13 ip-30-7-0-23 mysqld: OS WAIT ARRAY INFO: signal count 4

Nov 23 22:59:13 ip-30-7-0-23 mysqld: RW-shared spins 0, rounds 8, OS waits 4

Nov 23 22:59:13 ip-30-7-0-23 mysqld: RW-excl spins 0, rounds 0, OS waits 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: RW-sx spins 0, rounds 0, OS waits 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Spin rounds per wait: 8.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: TRANSACTIONS

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Trx id counter 8974

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Purge done for trx's n:o < 8972 undo n:o < 0 state: running

Nov 23 22:59:13 ip-30-7-0-23 mysqld: History list length 81

Nov 23 22:59:13 ip-30-7-0-23 mysqld: LIST OF TRANSACTIONS FOR EACH SESSION:

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ---TRANSACTION 421161104051016, not started

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ---TRANSACTION 421161104050056, not started

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ---TRANSACTION 8969, ACTIVE 263 sec dropping table

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: MySQL thread id 7, OS thread handle 0x7f0b446f7300, query id 118 localhost root Unlocking tables

Nov 23 22:59:13 ip-30-7-0-23 mysqld: drop database axon

Nov 23 22:59:13 ip-30-7-0-23 mysqld: --------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: FILE I/O

Nov 23 22:59:13 ip-30-7-0-23 mysqld: --------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 0 state: waiting for completed aio requests (insert buffer thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 1 state: waiting for completed aio requests (log thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 2 state: waiting for completed aio requests (read thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 3 state: waiting for completed aio requests (read thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 4 state: waiting for completed aio requests (read thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 5 state: waiting for completed aio requests (read thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 6 state: waiting for completed aio requests (write thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 7 state: waiting for completed aio requests (write thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 8 state: waiting for completed aio requests (write thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O thread 9 state: waiting for completed aio requests (write thread)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ibuf aio reads:, log i/o's:, sync i/o's:

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pending flushes (fsync) log: 0; buffer pool: 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 313 OS file reads, 95 OS file writes, 30 OS fsyncs

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: -------------------------------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: INSERT BUFFER AND ADAPTIVE HASH INDEX

Nov 23 22:59:13 ip-30-7-0-23 mysqld: -------------------------------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Ibuf: size 1, free list len 0, seg size 2, 0 merges

Nov 23 22:59:13 ip-30-7-0-23 mysqld: merged operations:

Nov 23 22:59:13 ip-30-7-0-23 mysqld: insert 0, delete mark 0, delete 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: discarded operations:

Nov 23 22:59:13 ip-30-7-0-23 mysqld: insert 0, delete mark 0, delete 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 1 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 1 buffer(s)

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0.00 hash searches/s, 0.00 non-hash searches/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ---

Nov 23 22:59:13 ip-30-7-0-23 mysqld: LOG

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ---

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Log sequence number 1759389

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Log flushed up to   1759389

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pages flushed up to 1759389

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Last checkpoint at  1757801

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0 pending log flushes, 0 pending chkp writes

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 20 log i/o's done, 0.00 log i/o's/second

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ----------------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: BUFFER POOL AND MEMORY

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ----------------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Total large memory allocated 138215424

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Dictionary memory allocated 251473

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Buffer pool size   8192

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Free buffers       7867

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Database pages     323

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Old database pages 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Modified db pages  0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Percent of dirty pages(LRU & free pages): 0.000

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Max dirty pages percent: 75.000

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pending reads 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pending writes: LRU 0, flush list 0, single page 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pages made young 0, not young 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0.00 youngs/s, 0.00 non-youngs/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pages read 284, created 39, written 62

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0.00 reads/s, 0.00 creates/s, 0.00 writes/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: No buffer pool page gets since the last printout

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: LRU len: 323, unzip_LRU len: 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: I/O sum[0]:cur[0], unzip sum[0]:cur[0]

Nov 23 22:59:13 ip-30-7-0-23 mysqld: --------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ROW OPERATIONS

Nov 23 22:59:13 ip-30-7-0-23 mysqld: --------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0 queries inside InnoDB, 0 queries in queue

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0 read views open inside InnoDB

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Process ID=4049, Main thread ID=139685452039936, state: enforcing dict cache limit

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Number of rows inserted 0, updated 0, deleted 0, read 259

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: Number of system rows inserted 0, updated 0, deleted 0, read 0

Nov 23 22:59:13 ip-30-7-0-23 mysqld: 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ----------------------------

Nov 23 22:59:13 ip-30-7-0-23 mysqld: END OF INNODB MONITOR OUTPUT

Nov 23 22:59:13 ip-30-7-0-23 mysqld: ============================

Nov 23 22:59:20 ip-30-7-0-23 mysqld: 2016-11-23 22:59:20 139686369522432 [Warning] InnoDB: Waited 270 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:59:21 ip-30-7-0-23 mysqld: InnoDB: ###### Diagnostic info printed to the standard error stream

Nov 23 22:59:22 ip-30-7-0-23 mysqld: 2016-11-23 22:59:22 139685468825344 [Warning] InnoDB: A long semaphore wait:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 272.00 seconds the semaphore:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:22 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:22 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:22 ip-30-7-0-23 mysqld: 2016-11-23 22:59:22 139685468825344 [Warning] InnoDB: A long semaphore wait:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: --Thread 139685452039936 has waited at srv0srv.cc line 2243 for 271.00 seconds the semaphore:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: X-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:22 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:22 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:22 ip-30-7-0-23 mysqld: 2016-11-23 22:59:22 139685468825344 [Note] InnoDB: A semaphore wait:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 272.00 seconds the semaphore:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:22 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:22 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:22 ip-30-7-0-23 mysqld: 2016-11-23 22:59:22 139685468825344 [Note] InnoDB: A semaphore wait:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: --Thread 139685452039936 has waited at srv0srv.cc line 2243 for 271.00 seconds the semaphore:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: X-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:22 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:22 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:22 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:22 ip-30-7-0-23 mysqld: InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

Nov 23 22:59:22 ip-30-7-0-23 mysqld: InnoDB: Pending preads 0, pwrites 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: =====================================

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 2016-11-23 22:59:33 0x7f0b0e3fd700 INNODB MONITOR OUTPUT

Nov 23 22:59:33 ip-30-7-0-23 mysqld: =====================================

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Per second averages calculated from the last 20 seconds

Nov 23 22:59:33 ip-30-7-0-23 mysqld: -----------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: BACKGROUND THREAD

Nov 23 22:59:33 ip-30-7-0-23 mysqld: -----------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 496 srv_idle

Nov 23 22:59:33 ip-30-7-0-23 mysqld: srv_master_thread log flush and writes: 497

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ----------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: SEMAPHORES

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ----------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: OS WAIT ARRAY INFO: reservation count 6

Nov 23 22:59:33 ip-30-7-0-23 mysqld: --Thread 139685435254528 has waited at row0purge.cc line 861 for 283.00 seconds the semaphore:

Nov 23 22:59:33 ip-30-7-0-23 mysqld: S-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:33 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:33 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:33 ip-30-7-0-23 mysqld: --Thread 139685452039936 has waited at srv0srv.cc line 2243 for 282.00 seconds the semaphore:

Nov 23 22:59:33 ip-30-7-0-23 mysqld: X-lock on RW-latch at 0x7f0b3f83c920 created in file dict0dict.cc line 1248

Nov 23 22:59:33 ip-30-7-0-23 mysqld: a writer (thread id 139686369522432) has reserved it in mode  exclusive

Nov 23 22:59:33 ip-30-7-0-23 mysqld: number of readers 0, waiters flag 1, lock_word: 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Last time read locked in file row0purge.cc line 861

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Last time write locked in file /home/buildbot/buildbot/build/mariadb-10.2.2/storage/innobase/row/row0mysql.cc line 4400

Nov 23 22:59:33 ip-30-7-0-23 mysqld: OS WAIT ARRAY INFO: signal count 4

Nov 23 22:59:33 ip-30-7-0-23 mysqld: RW-shared spins 0, rounds 8, OS waits 4

Nov 23 22:59:33 ip-30-7-0-23 mysqld: RW-excl spins 0, rounds 0, OS waits 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: RW-sx spins 0, rounds 0, OS waits 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Spin rounds per wait: 8.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: TRANSACTIONS

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Trx id counter 8974

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Purge done for trx's n:o < 8972 undo n:o < 0 state: running

Nov 23 22:59:33 ip-30-7-0-23 mysqld: History list length 81

Nov 23 22:59:33 ip-30-7-0-23 mysqld: LIST OF TRANSACTIONS FOR EACH SESSION:

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ---TRANSACTION 421161104051016, not started

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ---TRANSACTION 421161104050056, not started

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ---TRANSACTION 8969, ACTIVE 283 sec dropping table

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0 lock struct(s), heap size 1136, 0 row lock(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: MySQL thread id 7, OS thread handle 0x7f0b446f7300, query id 118 localhost root Unlocking tables

Nov 23 22:59:33 ip-30-7-0-23 mysqld: drop database axon

Nov 23 22:59:33 ip-30-7-0-23 mysqld: --------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: FILE I/O

Nov 23 22:59:33 ip-30-7-0-23 mysqld: --------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 0 state: waiting for completed aio requests (insert buffer thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 1 state: waiting for completed aio requests (log thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 2 state: waiting for completed aio requests (read thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 3 state: waiting for completed aio requests (read thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 4 state: waiting for completed aio requests (read thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 5 state: waiting for completed aio requests (read thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 6 state: waiting for completed aio requests (write thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 7 state: waiting for completed aio requests (write thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 8 state: waiting for completed aio requests (write thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O thread 9 state: waiting for completed aio requests (write thread)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ibuf aio reads:, log i/o's:, sync i/o's:

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pending flushes (fsync) log: 0; buffer pool: 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 313 OS file reads, 95 OS file writes, 30 OS fsyncs

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: -------------------------------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: INSERT BUFFER AND ADAPTIVE HASH INDEX

Nov 23 22:59:33 ip-30-7-0-23 mysqld: -------------------------------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Ibuf: size 1, free list len 0, seg size 2, 0 merges

Nov 23 22:59:33 ip-30-7-0-23 mysqld: merged operations:

Nov 23 22:59:33 ip-30-7-0-23 mysqld: insert 0, delete mark 0, delete 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: discarded operations:

Nov 23 22:59:33 ip-30-7-0-23 mysqld: insert 0, delete mark 0, delete 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 1 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 0 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Hash table size 34679, node heap has 1 buffer(s)

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0.00 hash searches/s, 0.00 non-hash searches/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ---

Nov 23 22:59:33 ip-30-7-0-23 mysqld: LOG

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ---

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Log sequence number 1759389

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Log flushed up to   1759389

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pages flushed up to 1759389

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Last checkpoint at  1757801

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0 pending log flushes, 0 pending chkp writes

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 20 log i/o's done, 0.00 log i/o's/second

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ----------------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: BUFFER POOL AND MEMORY

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ----------------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Total large memory allocated 138215424

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Dictionary memory allocated 251473

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Buffer pool size   8192

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Free buffers       7867

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Database pages     323

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Old database pages 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Modified db pages  0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Percent of dirty pages(LRU & free pages): 0.000

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Max dirty pages percent: 75.000

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pending reads 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pending writes: LRU 0, flush list 0, single page 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pages made young 0, not young 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0.00 youngs/s, 0.00 non-youngs/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pages read 284, created 39, written 62

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0.00 reads/s, 0.00 creates/s, 0.00 writes/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: No buffer pool page gets since the last printout

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: LRU len: 323, unzip_LRU len: 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: I/O sum[0]:cur[0], unzip sum[0]:cur[0]

Nov 23 22:59:33 ip-30-7-0-23 mysqld: --------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ROW OPERATIONS

Nov 23 22:59:33 ip-30-7-0-23 mysqld: --------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0 queries inside InnoDB, 0 queries in queue

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0 read views open inside InnoDB

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Process ID=4049, Main thread ID=139685452039936, state: enforcing dict cache limit

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Number of rows inserted 0, updated 0, deleted 0, read 259

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: Number of system rows inserted 0, updated 0, deleted 0, read 0

Nov 23 22:59:33 ip-30-7-0-23 mysqld: 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ----------------------------

Nov 23 22:59:33 ip-30-7-0-23 mysqld: END OF INNODB MONITOR OUTPUT

Nov 23 22:59:33 ip-30-7-0-23 mysqld: ============================

Nov 23 22:59:50 ip-30-7-0-23 mysqld: 2016-11-23 22:59:50 139686369522432 [Warning] InnoDB: Waited 300 seconds for ref-count on table: axon/routes space: 28

Nov 23 22:59:50 ip-30-7-0-23 mysqld: 2016-11-23 22:59:50 139686369522432 [Warning] InnoDB: After 300 seconds, gave up waiting for ref-count on table: axon/routes space: 28

Nov 23 22:59:50 ip-30-7-0-23 mysqld: 2016-11-23 22:59:50 139686369522432 [Note] InnoDB: MySQL is trying to drop table `axon`.`routes` though there are still open handles to it. Adding the table to the background drop queue.

Nov 23 22:59:51 ip-30-7-0-23 mysqld: 2016-11-23 22:59:51 139685452039936 [Note] InnoDB: Dropped table `axon`.`routes` in background drop queue.

Nov 23 22:59:52 ip-30-7-0-23 mysqld: InnoDB: ###### Diagnostic info printed to the standard error stream

Observations:

The issue was not there in 10.0.x
OQGRAPH code has not changed between 10.0, 10.1 and 10.2
The issue only occurs on database drop. If I just drop the Innodb table then the issue does not occur. If I drop the OQGRAPH table first and then drop the database, the issue does not occur.

Attachments

Activity

Ascending order - Click to sort in descending order

richardeaxon created issue - 2016-11-23 23:27

Elena Stepanova added a comment - 2016-11-25 21:57

Ellerbrockr,

Thanks for the report.

There is obviously a problem here, but you say in the summary "InnoDB crash" – I don't see an actual crash, either in your log or on my instance. Did you see one, and if so, do you have a stack trace?

Elena Stepanova added a comment - 2016-11-25 21:57 Ellerbrockr , Thanks for the report. There is obviously a problem here, but you say in the summary "InnoDB crash" – I don't see an actual crash, either in your log or on my instance. Did you see one, and if so, do you have a stack trace?

Elena Stepanova made changes - 2016-11-25 21:58

Field	Original Value	New Value
Labels		need_feedback

richardeaxon added a comment - 2016-11-26 02:17

Hello Elena,

I thought if there are lots of messages as above then that's a crash. When I saw the last message:

Nov 23 22:59:52 ip-30-7-0-23 mysqld: InnoDB: ###### Diagnostic info printed to the standard error stream

Then I though that's a crash. The messages above are all I have, but its reproducible.

richardeaxon added a comment - 2016-11-26 02:17 Hello Elena, I thought if there are lots of messages as above then that's a crash. When I saw the last message: Nov 23 22:59:52 ip-30-7-0-23 mysqld: InnoDB: ###### Diagnostic info printed to the standard error stream Then I though that's a crash. The messages above are all I have, but its reproducible.

Elena Stepanova made changes - 2016-11-26 11:42

Status

Open [ 1 ]

Confirmed [ 10101 ]

Elena Stepanova made changes - 2016-11-26 11:42

Summary

Drop database with OQGRAPH table causes InnoDB crash

Drop database with OQGRAPH table causes InnoDB long semaphore wait

Elena Stepanova added a comment - 2016-11-26 11:43

Ellerbrockr, thanks. Yes, it's reproducible easily, I just needed to clarify the crash part so that we didn't miss anything.

Elena Stepanova added a comment - 2016-11-26 11:43 Ellerbrockr , thanks. Yes, it's reproducible easily, I just needed to clarify the crash part so that we didn't miss anything.

Elena Stepanova made changes - 2016-11-26 11:43

Fix Version/s		10.1 [ 16100 ]
Fix Version/s		10.2 [ 14601 ]
Affects Version/s		10.1 [ 16100 ]
Affects Version/s		10.2 [ 14601 ]
Assignee		Jan Lindström [ jplindst ]
Labels	need_feedback

Marko Mäkelä made changes - 2016-12-02 08:56

Assignee

Jan Lindström [ jplindst ]

Marko Mäkelä [ marko ]

Marko Mäkelä made changes - 2016-12-02 08:56

Status

Confirmed [ 10101 ]

In Progress [ 3 ]

Marko Mäkelä added a comment - 2016-12-02 09:15

I cannot repeat any hang with the current 10.1 using the following test:

diff --git a/storage/oqgraph/mysql-test/oqgraph/innodb_hang.test b/storage/oqgraph/mysql-test/oqgraph/innodb_hang.test

new file mode 100644

index 0000000..40067de

--- /dev/null

+++ b/storage/oqgraph/mysql-test/oqgraph/innodb_hang.test

@@ -0,0 +1,22 @@

+--source include/have_innodb.inc

+CREATE TABLE `routes` (

+  `orig_node_id` int(10) unsigned NOT NULL,

+  `dest_node_id` int(10) unsigned NOT NULL,

+  `weight` double NOT NULL,

+  PRIMARY KEY (`orig_node_id`,`dest_node_id`),

+  KEY `dest_node_id` (`dest_node_id`)

+) ENGINE=InnoDB;

+CREATE TABLE `routing` (

+  `latch` varchar(32) DEFAULT NULL,

+  `origid` bigint(20) unsigned DEFAULT NULL,

+  `destid` bigint(20) unsigned DEFAULT NULL,

+  `weight` double DEFAULT NULL,

+  `seq` bigint(20) unsigned DEFAULT NULL,

+  `linkid` bigint(20) unsigned DEFAULT NULL,

+  KEY `latch` (`latch`,`origid`,`destid`) USING HASH,

+  KEY `latch_2` (`latch`,`destid`,`origid`) USING HASH

+) ENGINE=OQGRAPH `data_table`='routes' `origid`='orig_node_id' `destid`='dest_node_id' `weight`='weight';

+DROP DATABASE test;

The test passes:

oqgraph.innodb_t 'xtradb'                [ pass ]      2

MTR's internal check of the test case 'oqgraph.innodb_t' failed.

…

-def	test	latin1	latin1_swedish_ci	NULL

…

-def	test	latin1	latin1_swedish_ci	NULL

I will try to repeat with InnoDB instead of XtraDB.

Marko Mäkelä added a comment - 2016-12-02 09:15 I cannot repeat any hang with the current 10.1 using the following test: diff --git a/storage/oqgraph/mysql-test/oqgraph/innodb_hang.test b/storage/oqgraph/mysql-test/oqgraph/innodb_hang.test new file mode 100644 index 0000000..40067de --- /dev/null +++ b/storage/oqgraph/mysql-test/oqgraph/innodb_hang.test @@ -0,0 +1,22 @@ +--source include/have_innodb.inc + +CREATE TABLE `routes` ( + `orig_node_id` int(10) unsigned NOT NULL, + `dest_node_id` int(10) unsigned NOT NULL, + `weight` double NOT NULL, + PRIMARY KEY (`orig_node_id`,`dest_node_id`), + KEY `dest_node_id` (`dest_node_id`) +) ENGINE=InnoDB; + +CREATE TABLE `routing` ( + `latch` varchar(32) DEFAULT NULL, + `origid` bigint(20) unsigned DEFAULT NULL, + `destid` bigint(20) unsigned DEFAULT NULL, + `weight` double DEFAULT NULL, + `seq` bigint(20) unsigned DEFAULT NULL, + `linkid` bigint(20) unsigned DEFAULT NULL, + KEY `latch` (`latch`,`origid`,`destid`) USING HASH, + KEY `latch_2` (`latch`,`destid`,`origid`) USING HASH +) ENGINE=OQGRAPH `data_table`='routes' `origid`='orig_node_id' `destid`='dest_node_id' `weight`='weight'; + +DROP DATABASE test; The test passes: oqgraph.innodb_t 'xtradb' [ pass ] 2 MTR's internal check of the test case 'oqgraph.innodb_t' failed. … -def test latin1 latin1_swedish_ci NULL … -def test latin1 latin1_swedish_ci NULL I will try to repeat with InnoDB instead of XtraDB.

Marko Mäkelä added a comment - 2016-12-02 09:38

No hang with InnoDB either (just some harmless warnings during startup, and an ignorable error about missing tables for persistent statistics):

oqgraph.innodb_hang 'innodb_plugin'      [ fail ]  Found warnings/errors in server log file!

        Test ended at 2016-12-02 11:31:01

line

2016-12-02 11:31:01 139757777870528 [Warning] InnoDB: New log files created, LSN=45883

2016-12-02 11:31:01 139757777870528 [Warning] InnoDB: Creating foreign key constraint system tables.

2016-12-02 11:31:01 7f1bdc4c4b00 InnoDB: Error: Table "mysql"."innodb_table_stats" not found.

^ Found warnings in /dev/shm/t/mysql-test/var/log/mysqld.1.err

Marko Mäkelä added a comment - 2016-12-02 09:38 No hang with InnoDB either (just some harmless warnings during startup, and an ignorable error about missing tables for persistent statistics): oqgraph.innodb_hang 'innodb_plugin' [ fail ] Found warnings/errors in server log file! Test ended at 2016-12-02 11:31:01 line 2016-12-02 11:31:01 139757777870528 [Warning] InnoDB: New log files created, LSN=45883 2016-12-02 11:31:01 139757777870528 [Warning] InnoDB: Creating foreign key constraint system tables. 2016-12-02 11:31:01 7f1bdc4c4b00 InnoDB: Error: Table "mysql"."innodb_table_stats" not found. ^ Found warnings in /dev/shm/t/mysql-test/var/log/mysqld.1.err

Marko Mäkelä made changes - 2016-12-02 09:38

Status

In Progress [ 3 ]

Stalled [ 10000 ]

Marko Mäkelä added a comment - 2016-12-02 09:46

The table name axon.routes in the error message is not exactly matching the description (which would imply the table name test.routes):

Nov 23 22:55:20 ip-30-7-0-23 mysqld: 2016-11-23 22:55:20 139686369522432 [Warning] InnoDB: Waited 30 seconds for ref-count on table: axon/routes space: 28

Was it actually DROP DATABASE axon? Were there other tables in the system? Can this be repeated on an empty server?
Which options were used?
The message appears to originate from the function fil_wait_crypt_bg_threads(), which is present in both InnoDB and XtraDB. It is a MariaDB addition that is not present in Oracle’s version of MySQL.

Marko Mäkelä added a comment - 2016-12-02 09:46 The table name axon.routes in the error message is not exactly matching the description (which would imply the table name test.routes): Nov 23 22:55:20 ip-30-7-0-23 mysqld: 2016-11-23 22:55:20 139686369522432 [Warning] InnoDB: Waited 30 seconds for ref-count on table: axon/routes space: 28 Was it actually DROP DATABASE axon? Were there other tables in the system? Can this be repeated on an empty server? Which options were used? The message appears to originate from the function fil_wait_crypt_bg_threads(), which is present in both InnoDB and XtraDB. It is a MariaDB addition that is not present in Oracle’s version of MySQL.

Marko Mäkelä made changes - 2016-12-02 09:50

Status

Stalled [ 10000 ]

In Progress [ 3 ]

richardeaxon added a comment - 2016-12-02 10:36 - edited

The test case was on an empty 10.2 server. Ignore the use of axon database as that was on a 10.1 server which also exhibited the issue.

There is a difference in your test though. I created the database and tables, then closed the connection and then from a new connection using the mysql client did a:

echo "drop database test;" | mysql

Elena was able to recreate the exact same scenario.

richardeaxon added a comment - 2016-12-02 10:36 - edited The test case was on an empty 10.2 server. Ignore the use of axon database as that was on a 10.1 server which also exhibited the issue. There is a difference in your test though. I created the database and tables, then closed the connection and then from a new connection using the mysql client did a: echo "drop database test;" | mysql Elena was able to recreate the exact same scenario.

Marko Mäkelä added a comment - 2016-12-02 11:08

I can repeat with InnoDB only:

CREATE DATABASE db;

CREATE TABLE db.t (a INT) ENGINE=InnoDB;

connect (con1,localhost,root,,);

BEGIN;SELECT * FROM db.t;

connection default;

DROP DATABASE db;

As far as I can tell, the bug is that the DROP DATABASE statement is ignoring the fact that there is an active transaction that has accessed a table inside the database (schema) that is being dropped. I would expect the DROP DATABASE to be blocked until the SELECT transaction is committed or rolled back.

InnoDB is hanging, because DROP DATABASE is waiting that there are no open handles to the table that is being dropped. Normally the only such open handles should be from InnoDB background threads, such updating persistent statistics.

A bit after this hanging point of code (which is not present in the upstream MySQL) InnoDB is working around this lack of proper locking by putting the table on a "background DROP TABLE queue".

	} else if (table->n_ref_count > 0 || table->n_rec_locks > 0) {

		ibool	added;

		added = row_add_table_to_background_drop_list(table->name);

		if (added) {

			ut_print_timestamp(stderr);

			fputs("  InnoDB: Warning: MySQL is"

			      " trying to drop table ", stderr);

			ut_print_name(stderr, trx, TRUE, table->name);

			fputs("\n"

			      "InnoDB: though there are still"

			      " open handles to it.\n"

			      "InnoDB: Adding the table to the"

			      " background drop queue.\n",

			      stderr);

I believe that in MySQL 5.7, the background drop table queue only kicks in for the error handling of CREATE TABLE…SELECT which invokes DROP TABLE.

Marko Mäkelä added a comment - 2016-12-02 11:08 I can repeat with InnoDB only: CREATE DATABASE db; CREATE TABLE db.t (a INT) ENGINE=InnoDB; connect (con1,localhost,root,,); BEGIN;SELECT * FROM db.t; connection default; DROP DATABASE db; As far as I can tell, the bug is that the DROP DATABASE statement is ignoring the fact that there is an active transaction that has accessed a table inside the database (schema) that is being dropped. I would expect the DROP DATABASE to be blocked until the SELECT transaction is committed or rolled back. InnoDB is hanging, because DROP DATABASE is waiting that there are no open handles to the table that is being dropped. Normally the only such open handles should be from InnoDB background threads, such updating persistent statistics. A bit after this hanging point of code (which is not present in the upstream MySQL) InnoDB is working around this lack of proper locking by putting the table on a "background DROP TABLE queue". } else if (table->n_ref_count > 0 || table->n_rec_locks > 0) { ibool added; added = row_add_table_to_background_drop_list(table->name); if (added) { ut_print_timestamp(stderr); fputs(" InnoDB: Warning: MySQL is" " trying to drop table ", stderr); ut_print_name(stderr, trx, TRUE, table->name); fputs("\n" "InnoDB: though there are still" " open handles to it.\n" "InnoDB: Adding the table to the" " background drop queue.\n", stderr); I believe that in MySQL 5.7, the background drop table queue only kicks in for the error handling of CREATE TABLE…SELECT which invokes DROP TABLE.

Marko Mäkelä made changes - 2016-12-02 11:11

Summary

Drop database with OQGRAPH table causes InnoDB long semaphore wait

DROP DATABASE disregards meta-data locks of a transaction

Marko Mäkelä added a comment - 2016-12-02 11:14

I think that the proper fix should be to make DROP DATABASE honor the MDL (meta-data lock).
In MySQL 5.7 in sql/mdl.h, there is

  enum enum_mdl_namespace { GLOBAL=0,

                            TABLESPACE,

                            SCHEMA,

                            TABLE,

I believe that MariaDB needs to implement the equivalent of SCHEMA namespace in addition to the TABLE namespace which MariaDB must have inherited from MySQL 5.5.

Marko Mäkelä added a comment - 2016-12-02 11:14 I think that the proper fix should be to make DROP DATABASE honor the MDL (meta-data lock). In MySQL 5.7 in sql/mdl.h, there is enum enum_mdl_namespace { GLOBAL=0, TABLESPACE, SCHEMA, TABLE, I believe that MariaDB needs to implement the equivalent of SCHEMA namespace in addition to the TABLE namespace which MariaDB must have inherited from MySQL 5.5.

Marko Mäkelä made changes - 2016-12-02 11:14

Assignee

Marko Mäkelä [ marko ]

Sergey Vojtovich [ svoj ]

Sergey Vojtovich added a comment - 2016-12-02 11:40

I'll check this bug, but why do you think MariaDB doesn't have SCHEMA namespace?

Sergey Vojtovich added a comment - 2016-12-02 11:40 I'll check this bug, but why do you think MariaDB doesn't have SCHEMA namespace?

Marko Mäkelä added a comment - 2016-12-05 15:31

The above quoted definition (except for TABLESPACE) does exist in the MariaDB code base, but I meant that the SCHEMA namespace is apparently not being implemented correctly in MariaDB meta-data locks, because it fails to conflict with table MDL within the schema.
(Note: the SCHEMA keyword is a synonym for DATABASE, in both MySQL and MariaDB.)

Marko Mäkelä added a comment - 2016-12-05 15:31 The above quoted definition (except for TABLESPACE) does exist in the MariaDB code base, but I meant that the SCHEMA namespace is apparently not being implemented correctly in MariaDB meta-data locks, because it fails to conflict with table MDL within the schema. (Note: the SCHEMA keyword is a synonym for DATABASE, in both MySQL and MariaDB.)

richardeaxon added a comment - 2017-03-21 21:52

Any indication if this issue will be resolved when 10.2 GA is released? The issue is rather annoying as I cannot just do a simple "drop database" during unit test runs for our application.

richardeaxon added a comment - 2017-03-21 21:52 Any indication if this issue will be resolved when 10.2 GA is released? The issue is rather annoying as I cannot just do a simple "drop database" during unit test runs for our application.

Sergey Vojtovich made changes - 2017-06-30 10:11

Summary

DROP DATABASE disregards meta-data locks of a transaction

Drop database with OQGRAPH table causes InnoDB long semaphore wait

Sergey Vojtovich added a comment - 2017-06-30 10:21

I wasn't able to reproduce this problem with original test case. I also don't see any wrong behaviour with test case provided by Marko. One doesn't need DROP DATABASE nor multiple connections to reproduce this. A bit simplified test case that worked for me (it adds SELECT compared to original test):

--source include/have_innodb.inc

CREATE TABLE `routes` (

  `orig_node_id` int(10) unsigned NOT NULL,

  `dest_node_id` int(10) unsigned NOT NULL,

  `weight` double NOT NULL,

  PRIMARY KEY (`orig_node_id`,`dest_node_id`),

  KEY `dest_node_id` (`dest_node_id`)

) ENGINE=InnoDB;

CREATE TABLE `routing` (

  `latch` varchar(32) DEFAULT NULL,

  `origid` bigint(20) unsigned DEFAULT NULL,

  `destid` bigint(20) unsigned DEFAULT NULL,

  `weight` double DEFAULT NULL,

  `seq` bigint(20) unsigned DEFAULT NULL,

  `linkid` bigint(20) unsigned DEFAULT NULL,

  KEY `latch` (`latch`,`origid`,`destid`) USING HASH,

  KEY `latch_2` (`latch`,`destid`,`origid`) USING HASH

) ENGINE=OQGRAPH `data_table`='routes' `origid`='orig_node_id' `destid`='dest_node_id' `weight`='weight';

SELECT * FROM routing;

DROP TABLE routes; # Should not hang

So the problem is OQGRAPH opens a table without acquiring MDL lock for "backing" table, even worse it holds this reference while TABLE object is not used (hangs in table cache). I expect this may cause a lot more issues than reported in this bug.

ATM there's no good fix on my mind. I doubt our SE API allows to open tables the way OQGRAPH opens them.

Sergey Vojtovich added a comment - 2017-06-30 10:21 I wasn't able to reproduce this problem with original test case. I also don't see any wrong behaviour with test case provided by Marko. One doesn't need DROP DATABASE nor multiple connections to reproduce this. A bit simplified test case that worked for me (it adds SELECT compared to original test): --source include/have_innodb.inc CREATE TABLE `routes` ( `orig_node_id` int(10) unsigned NOT NULL, `dest_node_id` int(10) unsigned NOT NULL, `weight` double NOT NULL, PRIMARY KEY (`orig_node_id`,`dest_node_id`), KEY `dest_node_id` (`dest_node_id`) ) ENGINE=InnoDB; CREATE TABLE `routing` ( `latch` varchar(32) DEFAULT NULL, `origid` bigint(20) unsigned DEFAULT NULL, `destid` bigint(20) unsigned DEFAULT NULL, `weight` double DEFAULT NULL, `seq` bigint(20) unsigned DEFAULT NULL, `linkid` bigint(20) unsigned DEFAULT NULL, KEY `latch` (`latch`,`origid`,`destid`) USING HASH, KEY `latch_2` (`latch`,`destid`,`origid`) USING HASH ) ENGINE=OQGRAPH `data_table`='routes' `origid`='orig_node_id' `destid`='dest_node_id' `weight`='weight'; SELECT * FROM routing; DROP TABLE routes; # Should not hang So the problem is OQGRAPH opens a table without acquiring MDL lock for "backing" table, even worse it holds this reference while TABLE object is not used (hangs in table cache). I expect this may cause a lot more issues than reported in this bug. ATM there's no good fix on my mind. I doubt our SE API allows to open tables the way OQGRAPH opens them.

Marko Mäkelä made changes - 2017-10-26 08:51

Summary

Drop database with OQGRAPH table causes InnoDB long semaphore wait

DROP DATABASE should not ignore the meta-data locks of active transactions

Marko Mäkelä made changes - 2017-10-26 08:52

Affects Version/s

5.5 [ 15800 ]

Marko Mäkelä made changes - 2017-10-26 08:52

Component/s

Storage Engine - OQGRAPH [ 10130 ]

Marko Mäkelä made changes - 2017-10-26 08:52

Fix Version/s		5.5 [ 15800 ]
Fix Version/s		10.0 [ 16000 ]
Fix Version/s		10.3 [ 22126 ]

Marko Mäkelä added a comment - 2017-10-26 09:02

Inside MariaDB 5.5.59, 10.0.33, 10.1.29, 10.2.10, I can confirm that DROP DATABASE is correctly waiting for the MDL (with a default timeout of 1 year, I suppose).

So, the problem indeed could be that OQGRAPH is accessing tables without MDL protection. Ideally, all internal table access inside InnoDB should be covered by MDL.

Marko Mäkelä added a comment - 2017-10-26 09:02 Inside MariaDB 5.5.59, 10.0.33, 10.1.29, 10.2.10, I can confirm that DROP DATABASE is correctly waiting for the MDL (with a default timeout of 1 year, I suppose). So, the problem indeed could be that OQGRAPH is accessing tables without MDL protection. Ideally, all internal table access inside InnoDB should be covered by MDL.

Marko Mäkelä made changes - 2017-10-26 09:02

Affects Version/s

5.5 [ 15800 ]

Marko Mäkelä made changes - 2017-10-26 09:02

Fix Version/s	5.5 [ 15800 ]
Fix Version/s	10.0 [ 16000 ]

Marko Mäkelä made changes - 2017-10-26 09:02

Component/s

Storage Engine - OQGRAPH [ 10130 ]

Sergey Vojtovich made changes - 2017-11-28 14:02

Status

In Progress [ 3 ]

Stalled [ 10000 ]

Sergey Vojtovich made changes - 2018-05-17 10:38

Summary

DROP DATABASE should not ignore the meta-data locks of active transactions

OQGRAPH should acquire meta-data locks on "backing" tables

Sergei Golubchik made changes - 2019-03-29 12:04

Fix Version/s

10.4 [ 22408 ]

Sergei Golubchik made changes - 2020-05-05 14:43

Priority

Major [ 3 ]

Minor [ 4 ]

Julien Fritsch made changes - 2020-11-17 12:47

Assignee

Sergey Vojtovich [ svoj ]

Julien Fritsch [ julien.fritsch ]

Julien Fritsch made changes - 2020-11-17 12:47

Assignee

Julien Fritsch [ julien.fritsch ]

Vicențiu Ciorbaru [ cvicentiu ]

Heinz Wiesinger added a comment - 2020-11-27 07:49

I started working on this a while ago, but eventually stalled because of lack of time to continue :-/
The current state of what I had can be found at https://github.com/pprkut/mariadb/tree/MDEV-11342-oqgraph-mdl with comments on remaining problems to solve at https://github.com/pprkut/mariadb/commit/44e36b5f01a377976339210b6e6246f0d8adbdac

I was still planning to come back to this eventually, if nobody beats me to it first, but I don't expect that to happen anytime soon
So in the meantime, perhaps this helps someone interested in fixing it.

Heinz Wiesinger added a comment - 2020-11-27 07:49 I started working on this a while ago, but eventually stalled because of lack of time to continue :-/ The current state of what I had can be found at https://github.com/pprkut/mariadb/tree/MDEV-11342-oqgraph-mdl with comments on remaining problems to solve at https://github.com/pprkut/mariadb/commit/44e36b5f01a377976339210b6e6246f0d8adbdac I was still planning to come back to this eventually, if nobody beats me to it first, but I don't expect that to happen anytime soon So in the meantime, perhaps this helps someone interested in fixing it.

Julien Fritsch made changes - 2020-12-01 12:38

Fix Version/s

10.1 [ 16100 ]

Sergei Golubchik made changes - 2021-12-06 21:35

Workflow

MariaDB v3 [ 78441 ]

MariaDB v4 [ 143495 ]

Vicențiu Ciorbaru made changes - 2022-01-18 06:42

Status

Stalled [ 10000 ]

Open [ 1 ]

Ralf Gebhardt made changes - 2022-08-04 09:20

Fix Version/s

10.2 [ 14601 ]

Julien Fritsch made changes - 2023-04-27 14:18

Fix Version/s

10.3 [ 22126 ]

Vlad Radu made changes - 2025-02-06 07:19

Labels

foundation

People

Assignee:: Vicențiu Ciorbaru

Reporter:: richardeaxon

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 2016-11-23 23:27

Updated:: 2025-02-06 07:19

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Activity

People

Dates

Git Integration