Assertion `m_lock_rows == RDB_LOCK_WRITE' failed in myrocks::ha_rocksdb::write_row upon concurrent CREATE TABLE and FLUSH TABLES WITH READ LOCK

[spetrunia]

This is originally from https://jira.mariadb.org/browse/MDEV-15816 . The issue is not necessarily reproducible but with I was able to reproduce reliably with a debug build of
ee761fc.

The testcase

# INSTALL SONAME 'ha_rocksdb';
 
CREATE TABLE t1 (i INT) ENGINE=MyISAM;
INSERT INTO t1 VALUES (1),(2);
 
CREATE TABLE t2 (i INT) ENGINE=MyISAM;
INSERT INTO t2 VALUES (1),(2);
 
--connect (con1,localhost,root,,test)
 
--connection default
HANDLER t2 OPEN h;
--send
  CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0;
 
--connection con1
SET lock_wait_timeout= 2;
FLUSH TABLES WITH READ LOCK;
 
# Cleanup
UNLOCK TABLES;
--disconnect con1
--connection default
--reap
DROP TABLE t1, t2, t3;

Crashes like this:

mysqltest: At line 18: query 'FLUSH TABLES WITH READ LOCK' failed: 2013: Lost connection to MySQL server during query

The crashing thread (it is running CREATE TABLE ... SELECT):

Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
62      ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x00000000013b7a63 in my_write_core (sig=6) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/mysys/stacktrace.c:469
#2  0x0000000000f7c39f in handle_fatal_signal (sig=6) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/signal_handler.cc:239
#3  <signal handler called>
#4  0x00007fc23789f267 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
#5  0x00007fc2378a0eca in __GI_abort () at abort.c:89
#6  0x00007fc23789803d in __assert_fail_base (fmt=0x7fc2379fa028 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x1f2e0af "m_lock_rows == RDB_LOCK_WRITE", file=file@entry=0x1f28a60 "/home/psergey/dev-git/mysql-5.6-rocksdb-look800/storage/rocksdb/ha_rocksdb.cc", line=line@entry=8933, function=function@entry=0x1f34a20 <myrocks::ha_rocksdb::write_row(unsigned char*)::__PRETTY_FUNCTION__> "virtual int myrocks::ha_rocksdb::write_row(uchar*)") at assert.c:92
#7  0x00007fc2378980f2 in __GI___assert_fail (assertion=0x1f2e0af "m_lock_rows == RDB_LOCK_WRITE", file=0x1f28a60 "/home/psergey/dev-git/mysql-5.6-rocksdb-look800/storage/rocksdb/ha_rocksdb.cc", line=8933, function=0x1f34a20 <myrocks::ha_rocksdb::write_row(unsigned char*)::__PRETTY_FUNCTION__> "virtual int myrocks::ha_rocksdb::write_row(uchar*)") at assert.c:101
#8  0x0000000001709109 in myrocks::ha_rocksdb::write_row (this=0x7fc214046270, buf=0x7fc214045190 "\377\001") at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/storage/rocksdb/ha_rocksdb.cc:8933
#9  0x0000000000e4638c in handler::ha_write_row (this=0x7fc214046270, buf=0x7fc214045190 "\377\001") at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/handler.cc:7906
#10 0x000000000101dafa in write_record (thd=0x3ef9850, table=0x7fc214045910, info=0x7fc214006a20, update=0x7fc214006a98) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_insert.cc:1889
#11 0x000000000102269a in select_insert::send_data (this=0x7fc2140069d8, values=...) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_insert.cc:3697
#12 0x000000000100f5ee in end_send (join=0x7fc214006b58, join_tab=0x7fc2140430b0, end_of_records=false) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_executor.cc:2821
#13 0x000000000100cadd in evaluate_join_record (join=0x7fc214006b58, join_tab=0x7fc214042db0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_executor.cc:1642
#14 0x000000000100c08e in sub_select (join=0x7fc214006b58, join_tab=0x7fc214042db0, end_of_records=false) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_executor.cc:1317
#15 0x000000000100b7f3 in do_select (join=0x7fc214006b58) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_executor.cc:953
#16 0x0000000001009678 in JOIN::exec (this=0x7fc214006b58) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_executor.cc:207
#17 0x000000000107a271 in mysql_execute_select (thd=0x3ef9850, select_lex=0x3efd560, free_join=true) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_select.cc:1133
#18 0x000000000107a59a in mysql_select (thd=0x3ef9850, tables=0x7fc214005df8, wild_num=0, fields=..., conds=0x7fc214006678, order=0x3efd728, group=0x3efd660, having=0x0, select_options=2416184064, result=0x7fc2140069d8, unit=0x3efcf08, select_lex=0x3efd560) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_select.cc:1254
#19 0x0000000001078215 in handle_select (thd=0x3ef9850, result=0x7fc2140069d8, setup_tables_done_option=0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_select.cc:125
#20 0x000000000104339c in mysql_execute_command (thd=0x3ef9850, statement_start_time=0x7fc234785a48, post_parse=0x7fc234785bf8) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:4150
#21 0x000000000104d48d in mysql_parse (thd=0x3ef9850, rawbuf=0x7fc214005630 "CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0", length=68, parser_state=0x7fc2347864e0, last_timer=0x7fc234785bf8, async_commit=0x7fc234785b6a "") at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:7893
#22 0x000000000103d788 in dispatch_command (command=COM_QUERY, thd=0x3ef9850, packet=0x3f0c281 "CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0", packet_length=68) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:1917
#23 0x000000000103b5e9 in do_command (thd=0x3ef9850) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:1191
#24 0x0000000000ff9882 in do_handle_one_connection (thd_arg=0x3ef9850) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_connect.cc:1142
#25 0x0000000000ff92a4 in handle_one_connection (arg=0x3ef9850) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_connect.cc:963
#26 0x00007fc2384686aa in start_thread (arg=0x7fc234787700) at pthread_create.c:333
#27 0x00007fc237970eed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Another relevant thread (it is running FLUSH TABLES WITH READ LOCK):

Thread 7 (Thread 0x7fc234736700 (LWP 15858)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00000000013bbc15 in safe_cond_timedwait (cond=0x3f10648, mp=0x3f105d8, abstime=0x7fc234733600, file=0x1d0fe40 "/home/psergey/dev-git/mysql-5.6-rocksdb-look800/include/mysql/psi/mysql_thread.h", line=1214) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/mysys/thr_mutex.c:278
#2  0x0000000000f52e7f in inline_mysql_cond_timedwait (that=0x3f10648, mutex=0x3f105d8, abstime=0x7fc234733600) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/include/mysql/psi/mysql_thread.h:1214
#3  0x0000000000f53bb3 in MDL_wait::timed_wait (this=0x3f105d8, owner=0x3f104f0, abs_timeout=0x7fc234733600, set_status_on_timeout=true, wait_state_name=0x2611f80 <MDL_key::m_namespace_to_wait_state_name>) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/mdl.cc:1344
#4  0x0000000000f5545a in MDL_context::acquire_lock_nsec (this=0x3f105d8, mdl_request=0x7fc234733690, lock_wait_timeout_nsec=2000000000) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/mdl.cc:2320
#5  0x000000000120d444 in Global_read_lock::lock_global_read_lock (this=0x3f13498, thd=0x3f104f0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/lock.cc:1036
#6  0x000000000106ff70 in reload_acl_and_cache (thd=0x3f104f0, options=16388, tables=0x0, write_to_binlog=0x7fc234733ca0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_reload.cc:241
#7  0x000000000104705b in mysql_execute_command (thd=0x3f104f0, statement_start_time=0x7fc234734a48, post_parse=0x7fc234734bf8) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:5404
#8  0x000000000104d48d in mysql_parse (thd=0x3f104f0, rawbuf=0x7fc218004fc0 "FLUSH TABLES WITH READ LOCK", length=27, parser_state=0x7fc2347354e0, last_timer=0x7fc234734bf8, async_commit=0x7fc234734b6a "") at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:7893
#9  0x000000000103d788 in dispatch_command (command=COM_QUERY, thd=0x3f104f0, packet=0x3f159d1 "FLUSH TABLES WITH READ LOCK", packet_length=27) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:1917
#10 0x000000000103b5e9 in do_command (thd=0x3f104f0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_parse.cc:1191
#11 0x0000000000ff9882 in do_handle_one_connection (thd_arg=0x3f104f0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_connect.cc:1142
#12 0x0000000000ff92a4 in handle_one_connection (arg=0x3f104f0) at /home/psergey/dev-git/mysql-5.6-rocksdb-look800/sql/sql_connect.cc:963
#13 0x00007fc2384686aa in start_thread (arg=0x7fc234736700) at pthread_create.c:333
#14 0x00007fc237970eed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Stack traces of all threads (just in case): https://gist.github.com/spetrunia/159eba9a40a8d34e592a0b7853bb057a

[spetrunia]

So, the crash happens with this scenario:

• CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 starts running. It sets m_lock_rows=RDB_LOCK_WRITE

• FLUSH TABLES WITH READ LOCK starts executing

• It is not able to get locks for all tables that it needs immediately.

• It attempts to "notify" the lock holder that it is waiting for a lock:

  #0  myrocks::ha_rocksdb::store_lock (this=0x7fffbc03c7c8, thd=0x7fffc0000ba0, to=0x7fffc0011220, lock_type=TL_IGNORE) at /home/psergey/dev-git/10.2-r11/storage/rocksdb/ha_rocksdb.cc:10538
  #1  0x0000555555e955bf in get_lock_data (thd=0x7fffc0000ba0, table_ptr=0x7fffe84b7d20, count=1, flags=2) at /home/psergey/dev-git/10.2-r11/sql/lock.cc:794
  #2  0x0000555555e94ddf in mysql_lock_abort_for_thread (thd=0x7fffc0000ba0, table=0x7fffbc03bbc0) at /home/psergey/dev-git/10.2-r11/sql/lock.cc:624
  #3  0x0000555555ac0095 in THD::notify_shared_lock (this=0x7fffc0000ba0, ctx_in_use=0x7fffbc000bd8, needs_thr_lock_abort=true) at /home/psergey/dev-git/10.2-r11/sql/sql_class.cc:1959
  #4  0x0000555555c61815 in MDL_lock::notify_conflicting_locks (this=0x555557a82380, ctx=0x7fffc0000cc8) at /home/psergey/dev-git/10.2-r11/sql/mdl.cc:506
  #5  0x0000555555c5f3cd in MDL_context::acquire_lock (this=0x7fffc0000cc8, mdl_request=0x7fffe84b8350, lock_wait_timeout=2) at /home/psergey/dev-git/10.2-r11/sql/mdl.cc:2156
  #6  0x0000555555e95dbb in Global_read_lock::lock_global_read_lock (this=0x7fffc0003fe0, thd=0x7fffc0000ba0) at /home/psergey/dev-git/10.2-r11/sql/lock.cc:1023

• this causes ha_rocksdb::store_lock(RDB_LOCK_NONE) to be called.
• the code in that function sets m_lock_rows=RDB_LOCK_NONE. This is incorrect as the intent of this store_lock call is to fill the lock structure, not to obtain the lock.
• CREATE TABLE ... SELECT continues running and hits an assert when it unexpectedly finds that m_lock_rows==RDB_LOCK_NONE

[minggr]

To make it easier for debug, I can reproduce this bug just as below steps.

client 1:
USE test;
CREATE TABLE t1 (i INT) ENGINE=MyISAM;
HANDLER t1 OPEN h;
CREATE TABLE t2 (i INT) ENGINE=RocksDB;
LOCK TABLES t2 WRITE;

client 2:
FLUSH TABLES WITH READ LOCK;

client 1:
INSERT INTO t2 VALUES (1);

"HANDLER t1 OPEN h;" is the key step to reproduce this bug, because it sets needs_thr_lock_abort to true in THD::notify_shared_lock(...)

#0  MDL_context::set_needs_thr_lock_abort (this=0x2c8b608, needs_thr_lock_abort=true) at /workspace/mysql/sql/mdl.h:819
#1  0x0000000000fbae79 in mysql_ha_open_table (thd=0x2c8b520, hash_tables=0x7fffdc01a070) at /workspace/mysql/sql/sql_handler.cc:358
#2  0x0000000000fbaa68 in Sql_cmd_handler_open::execute (this=0x7fffdc005c88, thd=0x2c8b520) at /workspace/mysql/sql/sql_handler.cc:265
#3  0x0000000000fec871 in mysql_execute_command (thd=0x2c8b520, statement_start_time=0x7ffff7e8d868, post_parse=0x7ffff7e8e9e8) at /workspace/mysql/sql/sql_parse.cc:6209
#4  0x0000000000ff06b9 in mysql_parse (thd=0x2c8b520, rawbuf=0x7fffdc005630 "HANDLER t1 OPEN h", length=17, parser_state=0x7ffff7e8e280, last_timer=0x7ffff7e8e9e8, 
    async_commit=0x7ffff7e8e9e7 "") at /workspace/mysql/sql/sql_parse.cc:7895
#5  0x0000000000fe128c in dispatch_command (command=COM_QUERY, thd=0x2c8b520, packet=0x2c9de21 "HANDLER t1 OPEN h", packet_length=17) at /workspace/mysql/sql/sql_parse.cc:1919
#6  0x0000000000fdf303 in do_command (thd=0x2c8b520) at /workspace/mysql/sql/sql_parse.cc:1193
#7  0x0000000000f9fdb7 in do_handle_one_connection (thd_arg=0x2c8b520) at /workspace/mysql/sql/sql_connect.cc:1142
#8  0x0000000000f9f859 in handle_one_connection (arg=0x2c8b520) at /workspace/mysql/sql/sql_connect.cc:963
#9  0x00007ffff7bc6e25 in start_thread () from /lib64/libpthread.so.0
#10 0x00007ffff5d2e34d in clone () from /lib64/libc.so.6

Then "FLUSH TABLES WITH READ LOCK;" calls THD::notify_shared_lock() which checks "needs_thr_lock_abort" and then calls mysql_lock_abort_for_thread().

[minggr]

Hi @yoshinorim , any idea how to fix this bug?

[minggr]

Hi @lth , does below patch make sense?

diff --git a/storage/rocksdb/ha_rocksdb.cc b/storage/rocksdb/ha_rocksdb.cc
index b0a74b7..82c043f 100644
--- a/storage/rocksdb/ha_rocksdb.cc
+++ b/storage/rocksdb/ha_rocksdb.cc
@@ -10398,6 +10398,11 @@ THR_LOCK_DATA **ha_rocksdb::store_lock(THD *const thd, THR_LOCK_DATA **to,
 
   bool in_lock_tables = my_core::thd_in_lock_tables(thd);
 
+  /* Other thread calls this just to fill the lock structure */
+  if (thd != table->in_use && lock_type == TL_IGNORE) {
+    goto fill_lock;
+  }
+
   /* First, make a decision about MyRocks's internal locking */
   if (lock_type >= TL_WRITE_ALLOW_WRITE) {
     m_lock_rows = RDB_LOCK_WRITE;
@@ -10461,6 +10466,7 @@ THR_LOCK_DATA **ha_rocksdb::store_lock(THD *const thd, THR_LOCK_DATA **to,
     m_db_lock.type = lock_type;
   }
 
+fill_lock:
   *to++ = &m_db_lock;
 
   DBUG_RETURN(to);

[lth]

@minggr I'm looking at how innodb implements store_lock, and it seems like we just need to ignore setting m_lock_rows if lock_type == TL_IGNORE. Do you know why the first check on thd is needed?

[minggr]

I was thinking is there any case that the thread (who locked the table) calls store_lock(TL_IGNORE) and we can't ignore it? From my debug, seems there is no such case.

I'll send a patch.

[minggr]

Here is the merge request. #871