[MDEV-26587] Assertion `mutex->__data.__owner == 0' failed in pthread_mutex_lock/psi_mutex_lock Created: 2021-09-11  Updated: 2022-01-21  Resolved: 2022-01-21

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Insert, Locking, Storage Engine - Spider
Affects Version/s: 10.5, 10.6, 10.7
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Nayuta Yanagisawa (Inactive)
Resolution: Duplicate Votes: 0
Labels: affects-tests, not-10.2, not-10.3, not-10.4, regression

Issue Links:
Relates
relates to MDEV-26582 SIGSEGV in spider_db_bulk_insert and ... Closed

 Description    

INSTALL PLUGIN spider SONAME 'ha_spider.so';
 
CREATE TEMPORARY TABLE t (c INT,c2 INT) ENGINE=SPIDER UNION=(t,t2) INSERT_METHOD=LAST;
 
INSERT INTO t VALUES (1,0),(1,0),(1,0);
 
EXPLAIN INSERT INTO t SELECT 1 QUERY;

10.7.0 1bc82aaf0a7746c0921a94034aff2d51f0d75cd0 (Optimized)

 
mysqld: ../nptl/pthread_mutex_lock.c:81: __pthread_mutex_lock: Assertion `mutex->__data.__owner == 0' failed.

10.7.0 1bc82aaf0a7746c0921a94034aff2d51f0d75cd0 (Optimized)

 
Core was generated by `/test/MD040921-mariadb-10.7.0-linux-x86_64-opt/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x14cf14074700 (LWP 590265))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x000014cf15e34859 in __GI_abort () at abort.c:79
 
#2  0x000014cf15e34729 in __assert_fail_base (fmt=0x14cf15fca588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x14cf1635262d "mutex->__data.__owner == 0", file=0x14cf163525fa "../nptl/pthread_mutex_lock.c", line=81, function=<optimized out>) at assert.c:92
 
#3  0x000014cf15e45f36 in __GI___assert_fail (assertion=assertion@entry=0x14cf1635262d "mutex->__data.__owner == 0", file=file@entry=0x14cf163525fa "../nptl/pthread_mutex_lock.c", line=line@entry=81, function=function@entry=0x14cf16352790 <__PRETTY_FUNCTION__.10174> "__pthread_mutex_lock") at assert.c:101
 
#4  0x000014cf16346164 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x14cebc04f1d0) at ../nptl/pthread_mutex_lock.c:81
 
#5  0x00005577731e5e77 in psi_mutex_lock (that=that@entry=0x14cebc04f1d0, file=file@entry=0x14cf00f232a0 "/test/10.7_opt/storage/spider/spd_db_conn.cc", line=line@entry=6727) at /test/10.7_opt/mysys/my_thr_init.c:489
 
#6  0x000014cf00e6ddca in inline_mysql_mutex_lock (src_file=0x14cf00f232a0 "/test/10.7_opt/storage/spider/spd_db_conn.cc", src_line=6727, that=0x14cebc04f1d0) at /test/10.7_opt/include/mysql/psi/mysql_thread.h:746
 
#7  spider_db_bulk_insert (spider=spider@entry=0x14cebc022fd0, table=0x14cebc029008, copy_info=copy_info@entry=0x14cebc0233c0, bulk_end=bulk_end@entry=true) at /test/10.7_opt/storage/spider/spd_db_conn.cc:6727
 
#8  0x000014cf00eda474 in ha_spider::end_bulk_insert (this=0x14cebc022fd0) at /test/10.7_opt/storage/spider/ha_spider.cc:9896
 
#9  ha_spider::end_bulk_insert (this=0x14cebc022fd0) at /test/10.7_opt/storage/spider/ha_spider.cc:9887
 
#10 0x00005577732e697d in select_insert::abort_result_set (this=0x14cebc011cf8) at /test/10.7_opt/sql/sql_insert.cc:4294
 
#11 0x000055777332c966 in mysql_execute_command (thd=0x14cebc000c58, is_called_from_prepared_stmt=<optimized out>) at /test/10.7_opt/sql/sql_parse.cc:4735
 
#12 0x0000557773319456 in mysql_parse (thd=0x14cebc000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /test/10.7_opt/sql/sql_parse.cc:8036
 
#13 0x0000557773325345 in dispatch_command (command=COM_QUERY, thd=0x14cebc000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /test/10.7_opt/sql/sql_class.h:1358
 
#14 0x0000557773327217 in do_command (thd=0x14cebc000c58, blocking=blocking@entry=true) at /test/10.7_opt/sql/sql_parse.cc:1404
 
#15 0x0000557773442ae7 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /test/10.7_opt/sql/sql_connect.cc:1418
 
#16 0x0000557773442e2d in handle_one_connection (arg=arg@entry=0x55777596e548) at /test/10.7_opt/sql/sql_connect.cc:1312
 
#17 0x0000557773796298 in pfs_spawn_thread (arg=0x557775e10f78) at /test/10.7_opt/storage/perfschema/pfs.cc:2201
 
#18 0x000014cf16343609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#19 0x000014cf15f31293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

In debug builds this testcase leads to the stack seen in MDEV-26582:

10.7.0 1bc82aaf0a7746c0921a94034aff2d51f0d75cd0 (Debug)

 
Core was generated by `/test/MD040921-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  0x00001455e60bb248 in spider_db_bulk_insert (
 
    spider=spider@entry=0x1455c402d250, table=0x1455c405fb08, 
    copy_info=copy_info@entry=0x1455c402d640, bulk_end=bulk_end@entry=true)
 
    at /test/10.7_dbg/storage/spider/spd_db_conn.cc:6708
 
[Current thread is 1 (Thread 0x1455f4053700 (LWP 572880))]
 
(gdb) bt
 
#0  0x00001455e60bb248 in spider_db_bulk_insert (spider=spider@entry=0x1455c402d250, table=0x1455c405fb08, copy_info=copy_info@entry=0x1455c402d640, bulk_end=bulk_end@entry=true) at /test/10.7_dbg/storage/spider/spd_db_conn.cc:6708
 
#1  0x00001455e612c77a in ha_spider::end_bulk_insert (this=0x1455c402d250) at /test/10.7_dbg/storage/spider/ha_spider.cc:9896
 
#2  0x0000561a3677cd66 in handler::ha_end_bulk_insert (this=0x1455c402d250) at /test/10.7_dbg/sql/handler.cc:4990
 
#3  0x0000561a364252fe in select_insert::abort_result_set (this=0x1455c40151d8) at /test/10.7_dbg/sql/sql_insert.cc:4294
 
#4  0x0000561a36479882 in mysql_execute_command (thd=thd@entry=0x1455c4000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.7_dbg/sql/sql_parse.cc:4735
 
#5  0x0000561a36463ccb in mysql_parse (thd=thd@entry=0x1455c4000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1455f4052400) at /test/10.7_dbg/sql/sql_parse.cc:8036
 
#6  0x0000561a364728d0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1455c4000db8, packet=packet@entry=0x1455c400b739 "EXPLAIN INSERT INTO t SELECT 1 QUERY", packet_length=packet_length@entry=36, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_class.h:1358
 
#7  0x0000561a36475cd6 in do_command (thd=0x1455c4000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1404
 
#8  0x0000561a365ec0c8 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x561a39df3608, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
 
#9  0x0000561a365ec6cd in handle_one_connection (arg=arg@entry=0x561a39df3608) at /test/10.7_dbg/sql/sql_connect.cc:1312
 
#10 0x0000561a36a55ade in pfs_spawn_thread (arg=0x561a39cf2348) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
 
#11 0x000014560a5e3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#12 0x000014560a1d1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.13 (dbg), 10.5.13 (opt), 10.6.5 (dbg), 10.6.5 (opt), 10.7.0 (dbg), 10.7.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.41 (dbg), 10.2.41 (opt), 10.3.32 (dbg), 10.3.32 (opt), 10.4.22 (dbg), 10.4.22 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.35 (dbg), 5.7.35 (opt), 8.0.26 (dbg), 8.0.26 (opt)

 Comments   
Comment by Roel Van de Paar [ 2021-09-11 ]

In 10.5 optimized we see a slightly different stack:

10.5.13 0268b8712288d46fbd8a43fdef6bada399b68dff (Optimized)

 
mysqld: ../nptl/pthread_mutex_lock.c:81: __pthread_mutex_lock: Assertion `mutex->__data.__owner == 0' failed.

10.5.13 0268b8712288d46fbd8a43fdef6bada399b68dff (Optimized)

 
Core was generated by `/test/MD160821-mariadb-10.5.13-linux-x86_64-opt/bin/mysqld --no-defaults --core'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x1534a9fef700 (LWP 588436))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00001534ce099859 in __GI_abort () at abort.c:79
 
#2  0x00001534ce099729 in __assert_fail_base (fmt=0x1534ce22f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x1534ce5b762d "mutex->__data.__owner == 0", file=0x1534ce5b75fa "../nptl/pthread_mutex_lock.c", line=81, function=<optimized out>) at assert.c:92
 
#3  0x00001534ce0aaf36 in __GI___assert_fail (assertion=assertion@entry=0x1534ce5b762d "mutex->__data.__owner == 0", file=file@entry=0x1534ce5b75fa "../nptl/pthread_mutex_lock.c", line=line@entry=81, function=function@entry=0x1534ce5b7790 <__PRETTY_FUNCTION__.10174> "__pthread_mutex_lock") at assert.c:101
 
#4  0x00001534ce5ab164 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x15348404c9f0) at ../nptl/pthread_mutex_lock.c:81
 
#5  0x00001534a9ed9b36 in inline_mysql_mutex_lock (src_file=0x1534a9f722a0 "/test/10.5_opt/storage/spider/spd_db_conn.cc", src_line=6727, that=0x15348404c9f0) at /test/10.5_opt/include/mysql/psi/mysql_thread.h:752
 
#6  spider_db_bulk_insert (spider=spider@entry=0x153484028ae0, table=0x1534840249e8, copy_info=copy_info@entry=0x153484028ed0, bulk_end=bulk_end@entry=true) at /test/10.5_opt/storage/spider/spd_db_conn.cc:6727
 
#7  0x00001534a9f27424 in ha_spider::end_bulk_insert (this=0x153484028ae0) at /test/10.5_opt/storage/spider/ha_spider.cc:9896
 
#8  ha_spider::end_bulk_insert (this=0x153484028ae0) at /test/10.5_opt/storage/spider/ha_spider.cc:9887
 
#9  0x0000558c1ef171cd in select_insert::abort_result_set (this=0x153484011988) at /test/10.5_opt/sql/sql_insert.cc:4282
 
#10 0x0000558c1ef5d653 in mysql_execute_command (thd=0x153484000c58) at /test/10.5_opt/sql/sql_parse.cc:4794
 
#11 0x0000558c1ef49143 in mysql_parse (thd=0x153484000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /test/10.5_opt/sql/sql_parse.cc:8100
 
#12 0x0000558c1ef55925 in dispatch_command (command=COM_QUERY, thd=0x153484000c58, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /test/10.5_opt/sql/sql_class.h:1290
 
#13 0x0000558c1ef57eb2 in do_command (thd=0x153484000c58) at /test/10.5_opt/sql/sql_parse.cc:1370
 
#14 0x0000558c1f05e2e1 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x558c21b749a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_opt/sql/sql_connect.cc:1418
 
#15 0x0000558c1f05e75d in handle_one_connection (arg=arg@entry=0x558c21b749a8) at /test/10.5_opt/sql/sql_connect.cc:1312
 
#16 0x0000558c1f3ed5c9 in pfs_spawn_thread (arg=0x558c21afc1e8) at /test/10.5_opt/storage/perfschema/pfs.cc:2201
 
#17 0x00001534ce5a8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#18 0x00001534ce196293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Roel Van de Paar [ 2021-09-11 ]

This stack (pthread/mutex) is seen a lot in testing. iow, the filter placed (ref below) is removing a lot of trials. Other issues may be masked.

mutex->__data.__owner == 0|SIGABRT|__GI___pthread_mutex_lock|inline_mysql_mutex_lock|spider_db_bulk_insert|ha_spider::end_bulk_insert
 
mutex->__data.__owner == 0|SIGABRT|__GI___pthread_mutex_lock|psi_mutex_lock|inline_mysql_mutex_lock|spider_db_bulk_insert

Comment by Nayuta Yanagisawa (Inactive) [ 2021-09-14 ]

Roel Hi! This might be an elementary question but could you let me know what the word "optimized" mean in this context? I usually do debug build by the following command but how can I do "optimized" build? 

 cmake -DCMAKE_BUILD_TYPE=Debug .. && cmake --build . --config Debug -j8

Comment by Roel Van de Paar [ 2021-09-14 ]

nayuta-yanagisawa no worries. -opt and -dbg build cmake example commands below for comparison. Optimized binaries are close to what the customer uses, debug binaries have all debug assertions etc. enabled. Crashes, at times, may be reproducible on either/or or both.

/test/MD040921-mariadb-10.7.0-linux-x86_64-opt$ cat BUILD_CMD_CMAKE
 
cmake . -DWITH_SSL=bundled -DBUILD_CONFIG=mysql_release -DWITH_JEMALLOC=no -DWITH_TOKUDB=0 -DFEATURE_SET=community -DDEBUG_EXTNAME=OFF -DWITH_EMBEDDED_SERVER=0 -DENABLE_DOWNLOADS=1 -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/tmp/boost_292561 -DENABLED_LOCAL_INFILE=1 -DENABLE_DTRACE=0 -DWITH_PERFSCHEMA_STORAGE_ENGINE=1 -DWITH_ZLIB=bundled -DWITH_ROCKSDB=1 -DWITH_PAM=ON -DFORCE_INSOURCE_BUILD=1 -DCMAKE_C_FLAGS='-Og -march=native -mtune=native' -DCMAKE_CXX_FLAGS='-Og -march=native -mtune=native'


/test/MD040921-mariadb-10.7.0-linux-x86_64-dbg$ cat BUILD_CMD_CMAKE
 
cmake . -DWITH_SSL=bundled -DCMAKE_BUILD_TYPE=Debug -DBUILD_CONFIG=mysql_release -DWITH_TOKUDB=0 -DWITH_JEMALLOC=no -DFEATURE_SET=community -DDEBUG_EXTNAME=OFF -DWITH_EMBEDDED_SERVER=0 -DENABLE_DOWNLOADS=1 -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/tmp/boost_859248 -DENABLED_LOCAL_INFILE=1 -DENABLE_DTRACE=0 -DWITH_PERFSCHEMA_STORAGE_ENGINE=1 -DWITH_ZLIB=bundled -DWITH_ROCKSDB=1 -DWITH_PAM=ON -DFORCE_INSOURCE_BUILD=1 -DCMAKE_C_FLAGS='-Og -march=native -mtune=native' -DCMAKE_CXX_FLAGS='-Og -march=native -mtune=native' -DMYSQL_MAINTAINER_MODE=OFF

There are also some build scripts you can use if you like. 

https://github.com/mariadb-corporation/mariadb-qa/blob/master/build_mdpsms_dbg.sh
 
https://github.com/mariadb-corporation/mariadb-qa/blob/master/build_mdpsms_opt.sh

i.e.

cd ~
 
git clone --depth=1 https://github.com/mariadb-corporation/mariadb-qa.git
 
cd /test
 
git clone --depth=1 --recurse-submodules -j8 --branch=10.7 https://github.com/MariaDB/server.git 10.7
 
cd 10.7
 
~/mariadb-qa/build_mdpsms_opt.sh & sleep 120; ~/mariadb-qa/build_mdpsms_dbg.sh
 
#...wait for builds to finish...
 
cd /test/MD140921-mariadb-10.7.0-linux-x86_64-dbg  # for example, or -opt
 
~/mariadb-qa/startup.sh
 
./all  # this will bring you to a client with fresh data dir. Use ./stop, ./start, ./cl, ./kill, ./all and ./wipe where ./all includes ./wipe and ./kill (i.e. every time you run ./all you get a fresh data dir instance).

Let me know if you like more info on these. There are more scripts to build all versions at the same time 10.1-10.7 etc. as well as reducer scripts etc. Also scripts which can quickly check a given testcase against all versions, and so on. ramesh can assist too, we both use these scripts daily.

Comment by Nayuta Yanagisawa (Inactive) [ 2021-10-07 ]

Roel Thank you very much for your explanation (and sorry for my silence).

Comment by Nayuta Yanagisawa (Inactive) [ 2021-10-07 ]

MTR test case (should be placed at storage/spider/mysql-test/spider/bugfix/t):

--disable_query_log
 
--disable_result_log
 
--source ../../include/init_spider.inc
 
--enable_result_log
 
--enable_query_log
 
 
 
CREATE DATABASE auto_test_local;
 
USE auto_test_local;
 
 
 
--disable_warnings
 
CREATE TEMPORARY TABLE tbl_a (
 
    a INT,
 
    b INT
 
) ENGINE=SPIDER UNION=(tbl_a,tbl_b) INSERT_METHOD=LAST;
 
--enable_warnings
 
 
 
--error ER_CONNECT_TO_FOREIGN_DATA_SOURCE
 
INSERT INTO tbl_a VALUES (1,0),(1,0),(1,0);
 
--error ER_WRONG_VALUE_COUNT_ON_ROW
 
EXPLAIN INSERT INTO tbl_a SELECT 1 QUERY;
 
 
 
DROP DATABASE auto_test_local;
 
 
 
--disable_query_log
 
--disable_result_log
 
--source ../../include/deinit_spider.inc
 
--enable_result_log
 
--enable_query_log

Comment by Roel Van de Paar [ 2021-10-09 ]

No worries & thank you!

Comment by Nayuta Yanagisawa (Inactive) [ 2022-01-21 ]

I confirmed that the bug is no longer reproducible on 10.5 HEAD (a0f711e) and 10.7 HEAD (92a4e76).

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