Mutex deadlock (com_statistics, com_change_user, show full processlist)

General

Escalation

General

Escalation

Description

Multiple threads waiting for LOCK_Status:

(gdb) thread apply all frame 8
Thread 4101 (LWP 1659261):
#8  THD::release_resources (this=0x65, this@entry=0x7f7c3cb66dd0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4100 (LWP 1659256):
#8  THD::release_resources (this=0x65, this@entry=0x7f7c4199fb80) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4099 (LWP 1659251):
#8  THD::release_resources (this=0x65, this@entry=0x7f7a2d5ee150) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4098 (LWP 1659246):
#8  THD::release_resources (this=0x65, this@entry=0x7f7c3981b040) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4097 (LWP 1659240):
#8  THD::release_resources (this=0x65, this@entry=0x7f7c31d62ae0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4096 (LWP 1659235):
#8  THD::release_resources (this=0x65, this@entry=0x7f794aa495c0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4095 (LWP 1659230):
#8  THD::release_resources (this=0x65, this@entry=0x7f7c2e65a990) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
Thread 4094 (LWP 1659225):
#8  THD::release_resources (this=0x65, this@entry=0x7f7c250f77b0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1413
1413	  mysql_mutex_lock(&LOCK_status);
…

(gdb) print LOCK_status
$1 = {m_mutex = {m_u = {m_native = {__data = {__lock = 2, __count = 0, __owner = 1652020, __nusers = 1, __kind = 3, __spins = 94, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
        __size = "\002\000\000\000\000\000\000\000\064\065\031\000\001\000\000\000\003\000\000\000^", '\000' <repeats 18 times>, __align = 2}, m_safe_ptr = 0x2}}, m_psi = 0x55be7754e170}

Here, the owner of it is 1652020, which translates into:

[Switching to thread 224 (LWP 1652020)]
(gdb) bt
#0  0x00007f9e3d822170 in ?? ()
#1  0x00007f9e3d81a235 in ?? ()
#2  0x00007f9438490a10 in ?? ()
#3  0x000055be775d4608 in ?? ()
#4  0x000055be775d45d8 in ?? ()
#5  0x000055be713c9b55 in native_mutex_lock (mutex=0x55be775d4608) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
#6  my_mutex_lock (mp=0x55be775d4608) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
#7  inline_mysql_mutex_lock (src_file=0x55be73116fa8 "/mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.cc", src_line=290, 
    that=0x55be775d4608) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/mysql/psi/mysql_mutex.h:274
#8  Generic_mutex_lock<mysql_mutex_t>::Generic_mutex_lock (src_line=290, 
    src_file=0x55be73116fa8 "/mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.cc", mutex=0x55be775d4608, this=<synthetic pointer>)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/mutex_lock.h:47
#9  Global_THD_manager::do_for_all_thd_copy (this=0x55be775d23b0, func=func@entry=0x7f9438490a10)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.cc:290
#10 0x000055be71585ef3 in calc_sum_of_all_status (to=to@entry=0x7f9438490c20) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.h:216
#11 0x000055be71518e5b in dispatch_command (thd=0x7f7bd1d065a0, com_data=<optimized out>, command=COM_STATISTICS)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:2405
#12 0x000055be71519b52 in do_command (thd=thd@entry=0x7f7bd1d065a0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:1497
#13 0x000055be71689898 in handle_connection (arg=arg@entry=0x55be779c4320)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/conn_handler/connection_handler_per_thread.cc:308
#14 0x000055be72befdfd in pfs_spawn_thread (arg=0x55be7adbba10) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/storage/perfschema/pfs.cc:2987

That thread is executing command=COM_STATISTICS, and waits for:

(gdb) frame 6
#6  my_mutex_lock (mp=0x55be775d4608) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
190   return native_mutex_lock(&mp->m_u.m_native);
(gdb) print mp
$3 = (my_mutex_t *) 0x55be775d4608
(gdb) print *mp
$4 = {m_u = {m_native = {__data = {__lock = 2, __count = 0, __owner = 1652148, __nusers = 1, __kind = 3, __spins = 7, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
      __size = "\002\000\000\000\000\000\000\000\264\065\031\000\001\000\000\000\003\000\000\000\a", '\000' <repeats 18 times>, __align = 2}, m_safe_ptr = 0x2}}

This particular mutex is owned by thread 1652148, which translates to:

[Switching to thread 274 (LWP 1652148)]
#0  0x00007f9e3d822170 in ?? ()
(gdb) bt
#0  0x00007f9e3d822170 in ?? ()
#1  0x00007f9e3d81a235 in ?? ()
#2  0x00007f7ac294d018 in ?? ()
#3  0x00007f7aca6dd388 in ?? ()
#4  0x00007f7aca6dbef0 in ?? ()
#5  0x000055be715843df in native_mutex_lock (mutex=0x7f7aca6dd388) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
#6  my_mutex_lock (mp=0x7f7aca6dd388) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
#7  inline_mysql_mutex_lock (src_file=0x55be73885390 "/mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_show.cc", src_line=2786, that=0x7f7aca6dd388)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/mysql/psi/mysql_mutex.h:274
#8  Generic_mutex_lock<mysql_mutex_t>::Generic_mutex_lock (src_line=2786, 
    src_file=0x55be73885390 "/mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_show.cc", mutex=0x7f7aca6dd388, this=<synthetic pointer>)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/mutex_lock.h:47
#9  List_process_list::operator() (this=0x7f943838d7d0, inspect_thd=0xb) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_show.cc:2786
#10 0x000055be713c9cf6 in Do_THD::operator() (this=<synthetic pointer>, thd=<optimized out>)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.cc:78
#11 std::for_each<THD**, Do_THD> (__f=..., __last=<optimized out>, __first=0x7f7cc3f0c388) at /usr/include/c++/9/bits/stl_algo.h:3882
#12 Global_THD_manager::do_for_all_thd_copy (this=0x55be775d23b0, func=func@entry=0x7f943838d7d0)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.cc:303
#13 0x000055be71595677 in mysqld_list_processes (thd=0x7f7cc3fc08e0, user=0x0, verbose=<optimized out>, has_cursor=<optimized out>)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/mysqld_thd_manager.h:216
#14 0x000055be71595e73 in Sql_cmd_show_processlist::execute_inner (this=<optimized out>, thd=0x7f7cc3fc08e0)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.h:1469
#15 0x000055be71579d16 in Sql_cmd_dml::execute (this=0x7f7cc331c060, thd=0x7f7cc3fc08e0)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_select.cc:587
#16 0x000055be71511fc8 in mysql_execute_command (thd=0x7f7cc3fc08e0, first_level=<optimized out>)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:4933
#17 0x000055be715164d4 in dispatch_sql_command (thd=thd@entry=0x7f7cc3fc08e0, parser_state=parser_state@entry=0x7f943838eaf0, update_userstat=update_userstat@entry=false)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:5576
#18 0x000055be71518332 in dispatch_command (thd=0x7f7cc3fc08e0, com_data=<optimized out>, command=COM_QUERY)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:2125
#19 0x000055be71519b52 in do_command (thd=thd@entry=0x7f7cc3fc08e0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:1497
#20 0x000055be71689898 in handle_connection (arg=arg@entry=0x55be7a18e530)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/conn_handler/connection_handler_per_thread.cc:308
#21 0x000055be72befdfd in pfs_spawn_thread (arg=0x55be79b57d10) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/storage/perfschema/pfs.cc:2987
#22 0x00007f9e3d817609 in ?? ()
#23 0x0000000000000000 in ?? ()
(gdb) frame 18
#18 0x000055be71518332 in dispatch_command (thd=0x7f7cc3fc08e0, com_data=<optimized out>, command=COM_QUERY)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:2125
2125       dispatch_sql_command(thd, &parser_state, false);
(gdb) print thd->m_query_string
$37 = {str = 0x7f7cc331bba0 "SHOW FULL PROCESSLIST", length = 21}
#16 0x0000000000000000 in ?? ()

This thread is a command=COM_QUERY thread, that tries to execute SHOW FULL PROCESSLIST:

(gdb) frame 18
#18 0x000055be71518332 in dispatch_command (thd=0x7f7cc3fc08e0, com_data=<optimized out>, command=COM_QUERY)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:2125
2125       dispatch_sql_command(thd, &parser_state, false);
(gdb) print thd->m_query_string
$37 = {str = 0x7f7cc331bba0 "SHOW FULL PROCESSLIST", length = 21}

It waits for:

(gdb) print mp->m_u.m_native
$39 = {__data = {__lock = 2, __count = 0, __owner = 1652439, __nusers = 1, __kind = 3, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
  __size = "\002\000\000\000\000\000\000\000\327\066\031\000\001\000\000\000\003", '\000' <repeats 22 times>, __align = 2}
that's owned by 1652439:

(gdb) thread 554
[Switching to thread 554 (LWP 1652439)]
#0  0x00007f9e3d822170 in ?? ()
(gdb) bt
#0  0x00007f9e3d822170 in ?? ()
#1  0x00007f9e3d81a235 in ?? ()
#2  0x00007f8ee55fc9e0 in ?? ()
#3  0x000055be74751940 in ?? ()
#4  0x00007f7aca6dbef0 in ?? ()
#5  0x000055be71496ea7 in native_mutex_lock (mutex=<optimized out>) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
#6  my_mutex_lock (mp=<optimized out>) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/thr_mutex.h:190
#7  inline_mysql_mutex_lock (src_line=1171, src_file=0x55be7386fcf0 "/mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc", that=<optimized out>)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/include/mysql/psi/mysql_mutex.h:274
#8  THD::cleanup_connection (this=0x65, this@entry=0x7f7aca6dbef0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1171
#9  0x000055be71518bc7 in dispatch_command (thd=0x7f7aca6dbef0, com_data=<optimized out>, command=COM_CHANGE_USER)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:1976
#10 0x000055be71519b52 in do_command (thd=thd@entry=0x7f7aca6dbef0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_parse.cc:1497
#11 0x000055be71689898 in handle_connection (arg=arg@entry=0x55be7a9f7010)
    at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/conn_handler/connection_handler_per_thread.cc:308
#12 0x000055be72befdfd in pfs_spawn_thread (arg=0x55be7aca0520) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/storage/perfschema/pfs.cc:2987
#13 0x00007f9e3d817609 in ?? ()
#14 0x0000000000000000 in ?? ()

It's a command=COM_CHANGE_USER thread. This is used heavily by ProxySQL:

(gdb) print thd->m_query_string
$32 = {str = 0x0, length = 0}
(gdb) print thd->m_command
$33 = COM_CHANGE_USER

It waits for:

(gdb) frame 8
#8  THD::cleanup_connection (this=0x65, this@entry=0x7f7aca6dbef0) at /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.31-23/sql/sql_class.cc:1171
1171   mysql_mutex_lock(&LOCK_status);
(gdb) print LOCK_status.m_mutex.m_u.m_native.__data.__owner
$34 = 1652020

This thread waits for 1652020 (LWP 224) and here the cycle starts:

multiple \
          -> [ -> thread 224 (LWP 1652020) -> thread 274 (LWP 1652148) -> thread 554 (LWP 1652439) -> ]

Environment

None

AFFECTED CS IDs

CS0034673,CS0035428,CS0036005

Activity

Show:

Dmitry Lenev March 24, 2023 at 12:03 PM

Fix for the problem (https://github.com/percona/percona-server/pull/5025) was merged into 8.0 tree.

Dmitry Lenev March 20, 2023 at 4:09 PM

One possible way to reproduce the problem is to start the following script using MTR:

create database mysqlslap;

--disable_query_log
--disable_result_log

let $i = 10000000;

while ($i)
{
dec $i;

SELECT 1;
--change_user
}

--enable_query_log
--enable_result_log

And then execute the following commands in parallel:

mysqlslap --socket=var/tmp/mysqld.1.sock --concurrency=10 --iterations=10000 --query="flush status"

mysqlslap --socket=var/tmp/mysqld.1.sock -c 10 --iterations=10000 -q "select * from information_schema.processlist"

After some time server will deadlock and it will become impossible to run "show processlist" from another connection.

Note that "flush status" statement serves as replacement COM_STATISTICS in this case as it takes the same locks in same order.

Done

Details
Assignee
Unassigned
Reporter
Iwo Panowicz
Upstream Bug URL
https://bugs.mysql.com/bug.php?id=110494
Needs QA
Yes
Fix versions
8.0.33-25 (Q2 2023)
Affects versions
8.0.31-23 (Q4 2022)
Priority
Critical

Smart Checklist

Created March 16, 2023 at 12:13 PM

Updated March 6, 2024 at 9:45 AM

Resolved March 24, 2023 at 12:03 PM

Configure

Mutex deadlock (com_statistics, com_change_user, show full processlist)

Description

Environment

AFFECTED CS IDs

Activity

Dmitry Lenev March 24, 2023 at 12:03 PM

Dmitry Lenev March 20, 2023 at 4:09 PM

DetailsAssigneeUnassignedUnassignedReporterIwo PanowiczIwo PanowiczUpstream Bug URLhttps://bugs.mysql.com/bug.php?id=110494Needs QAYesFix versions8.0.33-25 (Q2 2023)Affects versions8.0.31-23 (Q4 2022)PriorityCritical

Details

Assignee

Reporter

Upstream Bug URL

Needs QA

Fix versions

Affects versions

Priority

Smart ChecklistOpen Smart Checklist

Smart Checklist

Details
Assignee
Unassigned
Reporter
Iwo Panowicz
Upstream Bug URL
https://bugs.mysql.com/bug.php?id=110494
Needs QA
Yes
Fix versions
8.0.33-25 (Q2 2023)
Affects versions
8.0.31-23 (Q4 2022)
Priority
Critical

Smart Checklist