[MDEV-11342] OQGRAPH should acquire meta-data locks on "backing" tables Created: 2016-11-23  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - OQGRAPH
Affects Version/s: 10.1, 10.1.19, 10.2.2, 10.2
Fix Version/s: 10.4

Type: Bug Priority: Minor
Reporter: richardeaxon Assignee: Vicențiu Ciorbaru
Resolution: Unresolved Votes: 0
Labels: None
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.

 Comments   
Comment by Elena Stepanova [ 2016-11-25 ]

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?

Comment by richardeaxon [ 2016-11-26 ]

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.

Comment by Elena Stepanova [ 2016-11-26 ]

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

Comment by Marko Mäkelä [ 2016-12-02 ]

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.

Comment by Marko Mäkelä [ 2016-12-02 ]

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

Comment by Marko Mäkelä [ 2016-12-02 ]

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.

Comment by richardeaxon [ 2016-12-02 ]

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.

Comment by Marko Mäkelä [ 2016-12-02 ]

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.

Comment by Marko Mäkelä [ 2016-12-02 ]

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.

Comment by Sergey Vojtovich [ 2016-12-02 ]

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

Comment by Marko Mäkelä [ 2016-12-05 ]

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

Comment by richardeaxon [ 2017-03-21 ]

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.

Comment by Sergey Vojtovich [ 2017-06-30 ]

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.

Comment by Marko Mäkelä [ 2017-10-26 ]

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.

Comment by Heinz Wiesinger [ 2020-11-27 ]

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.

Generated at Thu Feb 08 07:49:12 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.