[MDEV-15816] Assertion `m_lock_rows == RDB_LOCK_WRITE' failed in myrocks::ha_rocksdb::write_row upon concurrent CREATE TABLE and FLUSH TABLES WITH READ LOCK Created: 2018-04-08  Updated: 2018-09-12  Resolved: 2018-09-12

Status: Closed
Project: MariaDB Server
Component/s: Admin statements, Storage Engine - RocksDB
Affects Version/s: 10.2, 10.3
Fix Version/s: 10.2.18, 10.3.10

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: upstream


 Description   

Note: It fails for me every time, but the test case is still concurrent and non-deterministic. Run with --repeat if it doesn't fail right away.

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;

10.2 7b16291c3693

 
mysqld: /data/src/10.2/storage/rocksdb/ha_rocksdb.cc:8501: virtual int myrocks::ha_rocksdb::write_row(uchar*): Assertion `m_lock_rows == RDB_LOCK_WRITE' failed.
 
180409  1:53:36 [ERROR] mysqld got signal 6 ;
 
 
 
Thread 1 (Thread 0x7feb613f2700 (LWP 30573)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055fd9ab0e26a in my_write_core (sig=6) at /data/src/10.2/mysys/stacktrace.c:477
 
#2  0x000055fd9a3b15d6 in handle_fatal_signal (sig=6) at /data/src/10.2/sql/signal_handler.cc:305
 
#3  <signal handler called>
 
#4  0x00007feb6711cfcf in raise () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x00007feb6711e3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x00007feb67115e37 in __assert_fail_base () from /lib/x86_64-linux-gnu/libc.so.6
 
#7  0x00007feb67115ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x00007feb609f489b in myrocks::ha_rocksdb::write_row (this=0x7feb503814c8, buf=0x7feb50381cd8 "\377\001") at /data/src/10.2/storage/rocksdb/ha_rocksdb.cc:8501
 
#9  0x000055fd9a3c06f7 in handler::ha_write_row (this=0x7feb503814c8, buf=0x7feb50381cd8 "\377\001") at /data/src/10.2/sql/handler.cc:5971
 
#10 0x000055fd9a11e15e in write_record (thd=0x7feb50000b00, table=0x7feb503808c0, info=0x7feb50013960) at /data/src/10.2/sql/sql_insert.cc:1929
 
#11 0x000055fd9a123207 in select_insert::send_data (this=0x7feb50013920, values=...) at /data/src/10.2/sql/sql_insert.cc:3757
 
#12 0x000055fd9a1b2d0e in end_send (join=0x7feb50013a18, join_tab=0x7feb50015e90, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:19859
 
#13 0x000055fd9a1b07ea in evaluate_join_record (join=0x7feb50013a18, join_tab=0x7feb50015ae0, error=0) at /data/src/10.2/sql/sql_select.cc:18911
 
#14 0x000055fd9a1b028e in sub_select (join=0x7feb50013a18, join_tab=0x7feb50015ae0, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:18730
 
#15 0x000055fd9a1af68d in do_select (join=0x7feb50013a18, procedure=0x0) at /data/src/10.2/sql/sql_select.cc:18235
 
#16 0x000055fd9a189d8f in JOIN::exec_inner (this=0x7feb50013a18) at /data/src/10.2/sql/sql_select.cc:3566
 
#17 0x000055fd9a18923c in JOIN::exec (this=0x7feb50013a18) at /data/src/10.2/sql/sql_select.cc:3361
 
#18 0x000055fd9a18a407 in mysql_select (thd=0x7feb50000b00, tables=0x7feb50012d30, wild_num=0, fields=..., conds=0x7feb500135c8, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416184064, result=0x7feb50013920, unit=0x7feb500046a8, select_lex=0x7feb50004de0) at /data/src/10.2/sql/sql_select.cc:3761
 
#19 0x000055fd9a17ea4e in handle_select (thd=0x7feb50000b00, lex=0x7feb500045e0, result=0x7feb50013920, setup_tables_done_option=0) at /data/src/10.2/sql/sql_select.cc:376
 
#20 0x000055fd9a141b2a in mysql_execute_command (thd=0x7feb50000b00) at /data/src/10.2/sql/sql_parse.cc:3948
 
#21 0x000055fd9a14e252 in mysql_parse (thd=0x7feb50000b00, rawbuf=0x7feb500124f8 "CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0", length=68, parser_state=0x7feb613f1200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7914
 
#22 0x000055fd9a13c10d in dispatch_command (command=COM_QUERY, thd=0x7feb50000b00, packet=0x7feb50147241 "CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0", packet_length=68, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1815
 
#23 0x000055fd9a13aa70 in do_command (thd=0x7feb50000b00) at /data/src/10.2/sql/sql_parse.cc:1369
 
#24 0x000055fd9a2893bc in do_handle_one_connection (connect=0x55fd9db71130) at /data/src/10.2/sql/sql_connect.cc:1335
 
#25 0x000055fd9a289149 in handle_one_connection (arg=0x55fd9db71130) at /data/src/10.2/sql/sql_connect.cc:1241
 
#26 0x000055fd9a6a9326 in pfs_spawn_thread (arg=0x55fd9dad0010) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#27 0x00007feb68dec494 in start_thread (arg=0x7feb613f2700) at pthread_create.c:333
 
#28 0x00007feb671d293f in clone () from /lib/x86_64-linux-gnu/libc.so.6


Thread 3 (Thread 0x7feb600be700 (LWP 30597)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055fd9ab13ac7 in safe_cond_timedwait (cond=0x7feb2c000cd8, mp=0x7feb2c000c28, abstime=0x7feb600bc2c0, file=0x55fd9abff440 "/data/src/10.2/include/mysql/psi/mysql_thread.h", line=1175) at /data/src/10.2/mysys/thr_mutex.c:545
 
#2  0x000055fd9a292f06 in inline_mysql_cond_timedwait (that=0x7feb2c000cd8, mutex=0x7feb2c000c28, abstime=0x7feb600bc2c0, src_file=0x55fd9abff6ba "/data/src/10.2/sql/mdl.cc", src_line=1092) at /data/src/10.2/include/mysql/psi/mysql_thread.h:1175
 
#3  0x000055fd9a2942b9 in MDL_wait::timed_wait (this=0x7feb2c000c28, owner=0x7feb2c000bd8, abs_timeout=0x7feb600bc2c0, set_status_on_timeout=true, wait_state_name=0x55fd9b4e2c80 <MDL_key::m_namespace_to_wait_state_name>) at /data/src/10.2/sql/mdl.cc:1092
 
#4  0x000055fd9a295fb3 in MDL_context::acquire_lock (this=0x7feb2c000c28, mdl_request=0x7feb600bc350, lock_wait_timeout=2) at /data/src/10.2/sql/mdl.cc:2162
 
#5  0x000055fd9a4cbee1 in Global_read_lock::lock_global_read_lock (this=0x7feb2c003f40, thd=0x7feb2c000b00) at /data/src/10.2/sql/lock.cc:1023
 
#6  0x000055fd9a2bef06 in reload_acl_and_cache (thd=0x7feb2c000b00, options=16388, tables=0x0, write_to_binlog=0x7feb600bc910) at /data/src/10.2/sql/sql_reload.cc:250
 
#7  0x000055fd9a146c1d in mysql_execute_command (thd=0x7feb2c000b00) at /data/src/10.2/sql/sql_parse.cc:5396
 
#8  0x000055fd9a14e252 in mysql_parse (thd=0x7feb2c000b00, rawbuf=0x7feb2c011138 "FLUSH TABLES WITH READ LOCK", length=27, parser_state=0x7feb600bd200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7914
 
#9  0x000055fd9a13c10d in dispatch_command (command=COM_QUERY, thd=0x7feb2c000b00, packet=0x7feb2c008951 "FLUSH TABLES WITH READ LOCK", packet_length=27, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1815
 
#10 0x000055fd9a13aa70 in do_command (thd=0x7feb2c000b00) at /data/src/10.2/sql/sql_parse.cc:1369
 
#11 0x000055fd9a2893bc in do_handle_one_connection (connect=0x55fd9db6c8b0) at /data/src/10.2/sql/sql_connect.cc:1335
 
#12 0x000055fd9a289149 in handle_one_connection (arg=0x55fd9db6c8b0) at /data/src/10.2/sql/sql_connect.cc:1241
 
#13 0x000055fd9a6a9326 in pfs_spawn_thread (arg=0x55fd9dad0010) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#14 0x00007feb68dec494 in start_thread (arg=0x7feb600be700) at pthread_create.c:333
 
#15 0x00007feb671d293f in clone () from /lib/x86_64-linux-gnu/libc.so.6



 Comments   
Comment by Sergei Petrunia [ 2018-05-19 ] 

AA 140288073541376: query: CREATE TABLE t2 (i INT) ENGINE=MyISAM
 
AA 140288073541376: query: INSERT INTO t2 VALUES (1),(2)
 
AA 140288073541376: query: HANDLER t2 OPEN h
 
AA 140288073541376: query: CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0
 
AA 140288073238272: query: SET lock_wait_timeout= 2
 
AA 140288073238272: query: FLUSH TABLES WITH READ LOCK
 
AAA: 140288073541376: ha_rocksdb(0x7f973c15fcc8)::open called
 
AAA: 140288073541376: ha_rocksdb(0x7f973c15fcc8)::open setting m_lock_rows=RDB_LOCK_NONE
 
AAA: 140288073541376: ha_rocksdb(0x7f973c15fcc8)::store_lock(TL_WRITE)
 
AAA: 140288073541376: ha_rocksdb(0x7f973c15fcc8)::store_lock setting m_lock_rows=RDB_LOCK_WRITE
 
AAA: 140288073541376: ha_rocksdb(0x7f973c15fcc8)::external_lock(F_WRLCK)
 
AAA: 140288073541376: ha_rocksdb(0x7f973c15fcc8)::external_lock setting m_lock_rows=RDB_LOCK_WRITE
 
AAA: 140288073238272: ha_rocksdb(0x7f973c15fcc8)::store_lock( TL_IGNORE)
 
AAA: 140288073238272: ha_rocksdb(0x7f973c15fcc8)::store_lock setting m_lock_rows=RDB_LOCK_NONE
 
mysqld: /home/psergey/dev-git/10.2-r11/storage/rocksdb/ha_rocksdb.cc:9084: virtual int myrocks::ha_rocksdb::write_row(uchar*): Assertion `m_lock_rows == RDB_LOCK_WRITE' failed.

Comment by Sergei Petrunia [ 2018-05-19 ]

Indeed, FLUSH TABLES is calling store_lock(TL_IGNORE) :

(gdb) wher
 
  #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
 
  #7  0x0000555555c8843e in reload_acl_and_cache (thd=0x7fffc0000ba0, options=16388, tables=0x0, write_to_binlog=0x7fffe84b8910) at /home/psergey/dev-git/10.2-r11/sql/sql_reload.cc:250
 
  #8  0x0000555555b0f882 in mysql_execute_command (thd=0x7fffc0000ba0) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:5403
 
  #9  0x0000555555b17096 in mysql_parse (thd=0x7fffc0000ba0, rawbuf=0x7fffc0011128 "FLUSH TABLES WITH READ LOCK", length=27, parser_state=0x7fffe84b9200, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:7943
 
  #10 0x0000555555b04d88 in dispatch_command (command=COM_QUERY, thd=0x7fffc0000ba0, packet=0x7fffc0008941 "FLUSH TABLES WITH READ LOCK", packet_length=27, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:1823
 
  #11 0x0000555555b036b0 in do_command (thd=0x7fffc0000ba0) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:1375

The CREATE TABLE query is here:

  #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
 
  #1  0x00005555564de167 in safe_cond_timedwait (cond=0x7ffff0077120, mp=0x5555570c5400 <LOCK_item_func_sleep>, abstime=0x7ffff00770b0, file=0x55555666c780 "/home/psergey/dev-git/10.2-r11/include/mysql/psi/mysql_thread.h", line=1175) at /home/psergey/dev-git/10.2-r11/mysys/thr_mutex.c:545
 
  #2  0x0000555555df2c42 in inline_mysql_cond_timedwait (that=0x7ffff0077120, mutex=0x5555570c5400 <LOCK_item_func_sleep>, abstime=0x7ffff00770b0, src_file=0x55555666ce58 "/home/psergey/dev-git/10.2-r11/sql/item_func.cc", src_line=4023) at /home/psergey/dev-git/10.2-r11/include/mysql/psi/mysql_thread.h:1175
 
  #3  0x0000555555e01789 in Interruptible_wait::wait (this=0x7ffff0077100, cond=0x7ffff0077120, mutex=0x5555570c5400 <LOCK_item_func_sleep>) at /home/psergey/dev-git/10.2-r11/sql/item_func.cc:4023
 
  #4  0x0000555555e03050 in Item_func_sleep::val_int (this=0x7fffbc013460) at /home/psergey/dev-git/10.2-r11/sql/item_func.cc:4561
 
  #5  0x0000555555dbb283 in Arg_comparator::compare_int_signed (this=0x7fffbc013678) at /home/psergey/dev-git/10.2-r11/sql/item_cmpfunc.cc:943
 
  #6  0x0000555555dce6e2 in Arg_comparator::compare (this=0x7fffbc013678) at /home/psergey/dev-git/10.2-r11/sql/item_cmpfunc.h:87
 
  #7  0x0000555555dbd83d in Item_func_eq::val_int (this=0x7fffbc0135b8) at /home/psergey/dev-git/10.2-r11/sql/item_cmpfunc.cc:1776
 
  #8  0x0000555555b7953e in evaluate_join_record (join=0x7fffbc013a08, join_tab=0x7fffbc015a98, error=0) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:18790
 
  #9  0x0000555555b7930c in sub_select (join=0x7fffbc013a08, join_tab=0x7fffbc015a98, end_of_records=false) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:18734
 
  #10 0x0000555555b7870b in do_select (join=0x7fffbc013a08, procedure=0x0) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:18239
 
  #11 0x0000555555b52e0d in JOIN::exec_inner (this=0x7fffbc013a08) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:3570
 
  #12 0x0000555555b522ba in JOIN::exec (this=0x7fffbc013a08) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:3365
 
  #13 0x0000555555b53485 in mysql_select (thd=0x7fffbc000b00, tables=0x7fffbc012d20, wild_num=0, fields=..., conds=0x7fffbc0135b8, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416184064, result=0x7fffbc013910, unit=0x7fffbc0046a8, select_lex=0x7fffbc004de0) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:3765
 
  #14 0x0000555555b47a63 in handle_select (thd=0x7fffbc000b00, lex=0x7fffbc0045e0, result=0x7fffbc013910, setup_tables_done_option=0) at /home/psergey/dev-git/10.2-r11/sql/sql_select.cc:376
 
  #15 0x0000555555b0a78f in mysql_execute_command (thd=0x7fffbc000b00) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:3955
 
  #16 0x0000555555b17096 in mysql_parse (thd=0x7fffbc000b00, rawbuf=0x7fffbc0124e8 "CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0", length=68, parser_state=0x7ffff0078200, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:7943
 
  #17 0x0000555555b04d88 in dispatch_command (command=COM_QUERY, thd=0x7fffbc000b00, packet=0x7fffbc0088a1 "CREATE TABLE t3 ENGINE=RocksDB SELECT 1 FROM t1 WHERE SLEEP(0.5) = 0", packet_length=68, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:1823
 
  #18 0x0000555555b036b0 in do_command (thd=0x7fffbc000b00) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:1375
 
  #19 0x0000555555c528c2 in do_handle_one_connection (connect=0x555557ef1010) at /home/psergey/dev-git/10.2-r11/sql/sql_connect.cc:1335
 
  #20 0x0000555555c5264f in handle_one_connection (arg=0x555557ef1010) at /home/psergey/dev-git/10.2-r11/sql/sql_connect.cc:1241
 
  #21 0x00005555560e2528 in pfs_spawn_thread (arg=0x555557efbe00) at /home/psergey/dev-git/10.2-r11/storage/perfschema/pfs.cc:1862
 
  #22 0x00007ffff64fa6aa in start_thread (arg=0x7ffff0079700) at pthread_create.c:333
 
  #23 0x00007ffff5a02eed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Comment by Sergei Petrunia [ 2018-05-21 ]

Reproducible on upstream, filed as https://github.com/facebook/mysql-5.6/issues/838

Comment by Ming Lin [ 2018-08-21 ]

Here is the fix for upstream. I'll port it to mariadb once it's merged.
https://github.com/facebook/mysql-5.6/pull/871

Comment by Ming Lin [ 2018-08-22 ]

Here is the PR: https://github.com/MariaDB/server/pull/849

Comment by Sergei Petrunia [ 2018-09-12 ]

Set the PR status as "Merged". We've already got the patch with the merge from the upstream. minggr, thanks for the patch!

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