[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

View 10 older comments

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 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ä 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.

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.

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