[MDEV-18572] Thread executing DROP TABLE listed twice in SHOW ENGINE INNODB STATUS output Created: 2019-02-14  Updated: 2020-08-07

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.34
Fix Version/s: 10.1

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 1
Labels: None

Issue Links:
Blocks
is blocked by MDEV-11655 Transactional data dictionary Open
Relates
relates to MDEV-11655 Transactional data dictionary Open
relates to MDEV-18391 Print ENGINE INNODB STATUS in machine... Open
relates to MDEV-18698 Show InnoDB's internal background thr... Open
relates to MDEV-21566 Lock monitor doesn't print a name for... Closed
relates to MDEV-22087 Increase buffer size for query in SHO... Open
relates to MDEV-8069 DROP or rebuild of a large table may ... Closed
relates to MDEV-17237 thread IDs are printed in different f... Open
relates to MDEV-17238 Document special thread IDs used in S... Open
relates to MDEV-18429 Consistent non-locking reads do not a... Closed
relates to MDEV-18582 Port status variables related to SHOW... Closed
relates to MDEV-21330 Lock monitor doesn't print a semaphor... Closed
relates to MDEV-21390 lock_print_info_summary() should work... Closed

 Description   

I noticed today that a thread executing DROP TABLE is listed twice in SHOW ENGINE INNODB STATUS output.

Notice that both of the following threads have OS thread handle 0x2bab6976b700:

---TRANSACTION 29477290257, not started
MySQL thread id 270675, OS thread handle 0x2bab6976b700, query id 39700614954 10.1.1.37 appusr cleaning up
 
---TRANSACTION 29478037973, ACTIVE 39 sec dropping table
19 lock struct(s), heap size 2936, 18 row lock(s), undo log entries 8
MySQL thread id 270675, OS thread handle 0x2bab6976b700, query id 39700614954 10.1.1.37 appusr cleaning up
Trx read view will not see trx with id >= 29478080020, sees < 29478024097
Trx #rec lock waits 0 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC

0x2bab6976b700 is 48015208789760 in decimal, so we can see that the thread also held dict_sys->mutex and dict_operation_lock at the time:

--Thread 48015332652800 has waited at row0ins.cc line 1853 for 1.0000 seconds the semaphore:
S-lock on RW-latch at 0x564531fd5980 '&dict_operation_lock'
a writer (thread id 48015208789760) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0upd.cc line 190
Last time write locked in file row0mysql.cc line 3961
Holder thread 0 file not yet reserved line 0
--Thread 48014939903744 has waited at dict0boot.ic line 37 for 0.0000 seconds the semaphore:
Mutex at 0x2b6b4d814c68 '&dict_sys->mutex', lock var 1
Last time reserved by thread 48015208789760 in file not yet reserved line 0, waiters flag 1
--Thread 48022379951872 has waited at dict0dict.cc line 568 for 0.0000 seconds the semaphore:
Mutex at 0x2b6b4d814c68 '&dict_sys->mutex', lock var 1
Last time reserved by thread 48015208789760 in file not yet reserved line 0, waiters flag 1
--Thread 48015207757568 has waited at dict0boot.ic line 37 for 0.0000 seconds the semaphore:
Mutex at 0x2b6b4d814c68 '&dict_sys->mutex', lock var 1
Last time reserved by thread 48015208789760 in file not yet reserved line 0, waiters flag 1
--Thread 48015614957312 has waited at dict0dict.cc line 1141 for 0.0000 seconds the semaphore:
Mutex at 0x2b6b4d814c68 '&dict_sys->mutex', lock var 1
Last time reserved by thread 48015208789760 in file not yet reserved line 0, waiters flag 1
--Thread 48014967772928 has waited at dict0boot.ic line 37 for 0.0000 seconds the semaphore:
Mutex at 0x2b6b4d814c68 '&dict_sys->mutex', lock var 1
Last time reserved by thread 48015208789760 in file not yet reserved line 0, waiters flag 1
--Thread 48022577362688 has waited at dict0boot.ic line 37 for 0.0000 seconds the semaphore:
Mutex at 0x2b6b4d814c68 '&dict_sys->mutex', lock var 1
Last time reserved by thread 48015208789760 in file not yet reserved line 0, waiters flag 1
--Thread 48022621746944 has waited at row0mysql.cc line 3961 for 1.0000 seconds the semaphore:
X-lock on RW-latch at 0x564531fd5980 '&dict_operation_lock'
a writer (thread id 48015208789760) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0upd.cc line 190
Last time write locked in file row0mysql.cc line 3961
Holder thread 0 file not yet reserved line 0

Is the double listing an artifact of the ‘background DROP TABLE queue’ hack mentioned in the comments of MDEV-8069? One thread is the "real" user thread, and the other thread is the ‘background DROP TABLE queue’ hack thread? If so, can they be differentiated in the output somehow?



 Comments   
Comment by Marko Mäkelä [ 2019-07-23 ]

By design, DDL operations use two transactions inside InnoDB. The second transaction is created for updating the InnoDB data dictionary. Deadlocks and lock waits are prevented by dict_operation_lock a.k.a. dict_sys.latch and by the fact that internal transactions that access the InnoDB dictionary tables are not allowed to access any other tables.

Side note: This principle is being violated for the persistent statistics tables (mysql.innodb_table_stats and mysql.innodb_index_stats).

The extra transactions will go away when we remove the InnoDB internal SQL parser and the InnoDB internal data dictionary tables.

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