[MDEV-20690] Maria: lock order violation Created: 2019-09-27  Updated: 2019-10-03  Resolved: 2019-10-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 10.1, 10.2, 10.3, 10.4
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Eugene Kosov (Inactive) Assignee: Oleksandr Byelkin
Resolution: Not a Bug Votes: 1
Labels: None


 Description   

Bug was found using https://github.com/iovisor/bcc/blob/master/tools/deadlock.py

It requires installed BCC https://github.com/iovisor/bcc/blob/master/INSTALL.md

In one terminal I run:
./mtr main.create --repeat=1000
and in another one:
sudo ~/bin/deadlock_detector `pgrep mysqld` --binary /lib/x86_64-linux-gnu/libpthread.so.0

And this is a long issue report:

Tracing... Hit Ctrl-C to end.
----------------
Potential Deadlock Detected!
 
Cycle in lock order graph: Mutex M0 (0x0000000001f90ac0) => Mutex M1 (0x0000000002090c48) => Mutex M2 (0x0000000001990190) => Mutex M3 (0x0000000001a90318) => Mutex M4 (0x0000000001b904a0) => Mutex M5 (0x0000000001c90628) => Mutex M6 (0x0000000001d907b0) => Mutex M7 (0x0000000001e90938) => Mutex M0 (0x0000000001f90ac0)
 
Mutex M1 (0x0000000002090c48) acquired here while holding Mutex M0 (0x0000000001f90ac0) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 0000000001473068 flush_log_for_bitmap
@ 00000000014d0ee2 pagecache_fwrite
@ 00000000014d418e flush_cached_blocks
@ 00000000014d1846 flush_pagecache_blocks_with_filter
@ 0000000001445845 _ma_flush_table_files
@ 00000000014445dc maria_extra
@ 0000000001487ac9 ha_maria::extra(ha_extra_function)
@ 0000000000cb68f7 Sp_handler::sp_create_routine(THD*, sp_head const*) const
@ 0000000000da1ef8 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M0 (0x0000000001f90ac0) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 0000000001473068 flush_log_for_bitmap
@ 00000000014d0ee2 pagecache_fwrite
@ 00000000014d418e flush_cached_blocks
@ 00000000014d1846 flush_pagecache_blocks_with_filter
@ 0000000001445845 _ma_flush_table_files
@ 00000000014445dc maria_extra
@ 0000000001487ac9 ha_maria::extra(ha_extra_function)
@ 0000000000cb68f7 Sp_handler::sp_create_routine(THD*, sp_head const*) const
@ 0000000000da1ef8 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M2 (0x0000000001990190) acquired here while holding Mutex M1 (0x0000000002090c48) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001488323 ha_maria::external_lock(THD*, int)
@ 0000000000b0c253 handler::ha_external_lock(THD*, int)
@ 0000000000cbbcf1 unlock_external(THD*, TABLE**, unsigned int)
@ 0000000000cbbe3b mysql_unlock_tables(THD*, st_mysql_lock*, bool)
@ 0000000000d03bc5 close_thread_tables(THD*)
@ 0000000000da1f31 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M1 (0x0000000002090c48) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001488323 ha_maria::external_lock(THD*, int)
@ 0000000000b0c253 handler::ha_external_lock(THD*, int)
@ 0000000000cbbcf1 unlock_external(THD*, TABLE**, unsigned int)
@ 0000000000cbbe3b mysql_unlock_tables(THD*, st_mysql_lock*, bool)
@ 0000000000d03bc5 close_thread_tables(THD*)
@ 0000000000da1f31 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M3 (0x0000000001a90318) acquired here while holding Mutex M2 (0x0000000001990190) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014de213 maria_flush_log_for_page
@ 00000000014d0ee2 pagecache_fwrite
@ 00000000014d418e flush_cached_blocks
@ 00000000014d1846 flush_pagecache_blocks_with_filter
@ 0000000001445845 _ma_flush_table_files
@ 00000000014445dc maria_extra
@ 0000000001487ac9 ha_maria::extra(ha_extra_function)
@ 0000000000cb58e8 Sp_handler::sp_drop_routine_internal(THD*, Database_qualified_name const*, TABLE*) const
@ 0000000000cb70fa Sp_handler::sp_drop_routine(THD*, Database_qualified_name const*) const
@ 0000000000d9c925 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M2 (0x0000000001990190) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014de213 maria_flush_log_for_page
@ 00000000014d0ee2 pagecache_fwrite
@ 00000000014d418e flush_cached_blocks
@ 00000000014d1846 flush_pagecache_blocks_with_filter
@ 0000000001445845 _ma_flush_table_files
@ 00000000014445dc maria_extra
@ 0000000001487ac9 ha_maria::extra(ha_extra_function)
@ 0000000000cb58e8 Sp_handler::sp_drop_routine_internal(THD*, Database_qualified_name const*, TABLE*) const
@ 0000000000cb70fa Sp_handler::sp_drop_routine(THD*, Database_qualified_name const*) const
@ 0000000000d9c925 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M4 (0x0000000001b904a0) acquired here while holding Mutex M3 (0x0000000001a90318) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001488323 ha_maria::external_lock(THD*, int)
@ 0000000000b0c253 handler::ha_external_lock(THD*, int)
@ 0000000000cbbcf1 unlock_external(THD*, TABLE**, unsigned int)
@ 0000000000cbbe3b mysql_unlock_tables(THD*, st_mysql_lock*, bool)
@ 0000000000d03bc5 close_thread_tables(THD*)
@ 0000000000d9c93f mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M3 (0x0000000001a90318) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001488323 ha_maria::external_lock(THD*, int)
@ 0000000000b0c253 handler::ha_external_lock(THD*, int)
@ 0000000000cbbcf1 unlock_external(THD*, TABLE**, unsigned int)
@ 0000000000cbbe3b mysql_unlock_tables(THD*, st_mysql_lock*, bool)
@ 0000000000d03bc5 close_thread_tables(THD*)
@ 0000000000d9c93f mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M5 (0x0000000001c90628) acquired here while holding Mutex M4 (0x0000000001b904a0) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 000000000147ed1f maria_create
@ 0000000001489400 ha_maria::create(char const*, TABLE*, HA_CREATE_INFO*)
@ 0000000000b0806d handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*)
@ 0000000000b09563 ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*)
@ 0000000000e63d6a create_table_impl(THD*, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, char const*, DDL_options_st, HA_CREATE_INFO*, Alter_info*, int, bool*, st_key**, unsigned int*, st_mysql_const_unsigned_lex_string*)
@ 0000000000e63411 mysql_create_table_no_lock(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, Table_specification_st*, Alter_info*, bool*, int, TABLE_LIST*)
@ 0000000000e650fb mysql_create_like_table(THD*, TABLE_LIST*, TABLE_LIST*, Table_specification_st*)
@ 0000000000e72ca8 Sql_cmd_create_table_like::execute(THD*)
@ 0000000000d9b6f0 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M4 (0x0000000001b904a0) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 000000000147ed1f maria_create
@ 0000000001489400 ha_maria::create(char const*, TABLE*, HA_CREATE_INFO*)
@ 0000000000b0806d handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*)
@ 0000000000b09563 ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*)
@ 0000000000e63d6a create_table_impl(THD*, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, char const*, DDL_options_st, HA_CREATE_INFO*, Alter_info*, int, bool*, st_key**, unsigned int*, st_mysql_const_unsigned_lex_string*)
@ 0000000000e63411 mysql_create_table_no_lock(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, Table_specification_st*, Alter_info*, bool*, int, TABLE_LIST*)
@ 0000000000e650fb mysql_create_like_table(THD*, TABLE_LIST*, TABLE_LIST*, Table_specification_st*)
@ 0000000000e72ca8 Sql_cmd_create_table_like::execute(THD*)
@ 0000000000d9b6f0 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M6 (0x0000000001d907b0) acquired here while holding Mutex M5 (0x0000000001c90628) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 000000000149fcbb maria_delete_table
@ 0000000000b0183e ha_delete_table(THD*, handlerton*, char const*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, bool)
@ 0000000000e60446 mysql_rm_table_no_locks(THD*, TABLE_LIST*, bool, bool, bool, bool, bool, bool)
@ 0000000000e5f3f6 mysql_rm_table(THD*, TABLE_LIST*, bool, bool, bool)
@ 0000000000da064c mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M5 (0x0000000001c90628) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000015d2072 _db_enter_
@ 0000000000fe7c70 THD::create_and_open_tmp_table(st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*, bool)
@ 0000000000e63cf4 create_table_impl(THD*, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, st_mysql_const_lex_string const&, char const*, DDL_options_st, HA_CREATE_INFO*, Alter_info*, int, bool*, st_key**, unsigned int*, st_mysql_const_unsigned_lex_string*)
@ 0000000000e63411 mysql_create_table_no_lock(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, Table_specification_st*, Alter_info*, bool*, int, TABLE_LIST*)
@ 0000000000e650fb mysql_create_like_table(THD*, TABLE_LIST*, TABLE_LIST*, Table_specification_st*)
@ 0000000000e72ca8 Sql_cmd_create_table_like::execute(THD*)
@ 0000000000d9b6f0 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M7 (0x0000000001e90938) acquired here while holding Mutex M6 (0x0000000001d907b0) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001487cf5 ha_maria::implicit_commit(THD*, bool)
@ 0000000000da0d55 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M6 (0x0000000001d907b0) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001487cf5 ha_maria::implicit_commit(THD*, bool)
@ 0000000000da0d55 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M0 (0x0000000001f90ac0) acquired here while holding Mutex M7 (0x0000000001e90938) in Thread 18277 (mysqld):
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014bfe3f translog_buffer_flush
@ 00000000014be9ec translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001487cf5 ha_maria::implicit_commit(THD*, bool)
@ 0000000000da0d55 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Mutex M7 (0x0000000001e90938) previously acquired by the same Thread 18277 (mysqld) here:
@ 00007f52258cc8f0 __pthread_mutex_lock
@ 00000000014beae8 translog_flush_buffers
@ 00000000014c02c8 translog_flush
@ 00000000014dd880 ma_commit
@ 0000000001487cf5 ha_maria::implicit_commit(THD*, bool)
@ 0000000000da0d55 mysql_execute_command(THD*)
@ 0000000000d965b2 mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)
@ 0000000000d9306d dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)
@ 0000000000d96da4 do_command(THD*)
@ 0000000000ee9f19 do_handle_one_connection(CONNECT*)
@ 0000000000ee9d08 handle_one_connection
@ 0000000001537326 pfs_spawn_thread
@ 00007f52258ca182 start_thread
 
Could not find stack trace where Thread 18277 was created



 Comments   
Comment by Sergei Golubchik [ 2019-10-03 ]

This is a know false-positive. safe_mutex deadlock detector complains here too, that's why it was explicitly configured to ignore this mutex.

The comment near the declaration of st_translog_buffer::mutex explains it.

Generated at Thu Feb 08 09:01:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.