[MDEV-13602] rocksdb.index_merge_rocksdb2 failed in buildbot Created: 2017-08-21  Updated: 2017-09-12  Resolved: 2017-08-23

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - RocksDB, Tests
Affects Version/s: 10.2
Fix Version/s: 10.2.9

Type: Bug Priority: Minor
Reporter: Alice Sherepa Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1158/steps/test_1/logs/stdio

rocksdb.index_merge_rocksdb2             w2 [ fail ]
 
        Test ended at 2017-08-19 23:18:20
 
 
 
CURRENT_TEST: rocksdb.index_merge_rocksdb2
 
mysqltest: In included file "./include/index_merge1.inc": 
included from /mnt/buildbot/build/mariadb-10.2.9/storage/rocksdb/mysql-test/rocksdb/t/index_merge_rocksdb2.test at line 35:
 
At line 442: query 'LOCK TABLES t1 WRITE, t2 WRITE' failed: 4056: Can't execute updates on master with binlog_format != ROW.
 
 
 
The result from queries just before the failure was:
 
< snip >
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),(0,0),
 
(1,2);
 
LOCK TABLES t1 WRITE, t2 WRITE;



 Comments   
Comment by Sergei Petrunia [ 2017-08-21 ]

some notes

  • this reminds one of MDEV-13148 (but it should not cause a test failure, should it?)
  • ./include/index_merge1.inc files are different across upstream and MariaDB
  • Both have the LOCK TABLES statements, though
  • upstream has log_bin=1, binlog_format=ROW when executing the LOCK TABLES (and this produces no error)
  • MariaDB also has log_bin=1, binlog_format=ROW when executing the LOCK TABLES (and this DOES produce an error)
Comment by Sergei Petrunia [ 2017-08-22 ]

.. however internally when I stop at LOCK TABLES in debugger, I get binlog_format=1 which is BINLOG_FORMAT_STMT.

The value changes at the start of the LOCK TABLES statement here:

Hardware watchpoint 2: -location thd->variables.binlog_format
 
 
 
Old value = 2
 
New value = 1
 
THD::set_binlog_format_stmt (this=0x7fffc4000b00) at /home/psergey/dev-git/10.2/sql/sql_class.h:3697
 
(gdb) wher
 
#0  THD::set_binlog_format_stmt (this=0x7fffc4000b00) at /home/psergey/dev-git/10.2/sql/sql_class.h:3697
 
#1  0x0000555555b00211 in mysql_execute_command (thd=0x7fffc4000b00) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:3300
 
#2  0x0000555555b0e1c2 in mysql_parse (thd=0x7fffc4000b00, rawbuf=0x7fffc4012528 "LOCK TABLES t1 WRITE, t2 WRITE", length=30, parser_state=0x7fffea8a4200, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:7886
 
#3  0x0000555555afc1cd in dispatch_command (command=COM_QUERY, thd=0x7fffc4000b00, packet=0x7fffc418bd41 "LOCK TABLES t1 WRITE, t2 WRITE", packet_length=30, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:1812
 
#4  0x0000555555afab47 in do_command (thd=0x7fffc4000b00) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:1360
 
#5  0x0000555555c474b3 in do_handle_one_connection (connect=0x555557e723c0) at /home/psergey/dev-git/10.2/sql/sql_connect.cc:1354
 
#6  0x0000555555c47240 in handle_one_connection (arg=0x555557e723c0) at /home/psergey/dev-git/10.2/sql/sql_connect.cc:1260
 
#7  0x00005555560d1e5e in pfs_spawn_thread (arg=0x555557e90dd0) at /home/psergey/dev-git/10.2/storage/perfschema/pfs.cc:1862
 
#8  0x00007ffff67056aa in start_thread (arg=0x7fffea8a5700) at pthread_create.c:333
 
#9  0x00007ffff5c0deed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

That is, there is this piece of code in mysql_execute_command:

  /*
 
    Force statement logging for DDL commands to allow us to update
 
    privilege, system or statistic tables directly without the updates
 
    getting logged.
 
  */
 
  if (!(sql_command_flags[lex->sql_command] &
 
        (CF_CAN_GENERATE_ROW_EVENTS | CF_FORCE_ORIGINAL_BINLOG_FORMAT |
 
         CF_STATUS_COMMAND)))
 
    thd->set_binlog_format_stmt();

Comment by Sergei Petrunia [ 2017-08-22 ]

..
at the end of the LOCK TABLES statement it switches back here:

(gdb) c
 
Continuing.
 
Hardware watchpoint 2: -location thd->variables.binlog_format
 
 
 
Old value = 1
 
New value = 2
 
THD::set_binlog_format (this=0x7fffc4000b00, format=BINLOG_FORMAT_ROW, current_format=BINLOG_FORMAT_ROW) at /home/psergey/dev-git/10.2/sql/sql_class.h:3690
 
(gdb) wher
 
#0  THD::set_binlog_format (this=0x7fffc4000b00, format=BINLOG_FORMAT_ROW, current_format=BINLOG_FORMAT_ROW) at /home/psergey/dev-git/10.2/sql/sql_class.h:3690
 
#1  0x0000555555b09bcb in mysql_execute_command (thd=0x7fffc4000b00) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:6283
 
#2  0x0000555555b0e1c2 in mysql_parse (thd=0x7fffc4000b00, rawbuf=0x7fffc4012528 "LOCK TABLES t1 WRITE, t2 WRITE", length=30, parser_state=0x7fffea8a4200, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:7886
 
#3  0x0000555555afc1cd in dispatch_command (command=COM_QUERY, thd=0x7fffc4000b00, packet=0x7fffc418bd41 "LOCK TABLES t1 WRITE, t2 WRITE", packet_length=30, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:1812
 
#4  0x0000555555afab47 in do_command (thd=0x7fffc4000b00) at /home/psergey/dev-git/10.2/sql/sql_parse.cc:1360
 
#5  0x0000555555c474b3 in do_handle_one_connection (connect=0x555557e723c0) at /home/psergey/dev-git/10.2/sql/sql_connect.cc:1354
 
#6  0x0000555555c47240 in handle_one_connection (arg=0x555557e723c0) at /home/psergey/dev-git/10.2/sql/sql_connect.cc:1260
 
#7  0x00005555560d1e5e in pfs_spawn_thread (arg=0x555557e90dd0) at /home/psergey/dev-git/10.2/storage/perfschema/pfs.cc:1862
 
#8  0x00007ffff67056aa in start_thread (arg=0x7fffea8a5700) at pthread_create.c:333
 
#9  0x00007ffff5c0deed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Comment by Alice Sherepa [ 2017-08-28 ]

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1167/steps/test_2/logs/stdio
result content mismatch

rocksdb.index_merge_rocksdb2             w2 [ fail ]
 
        Test ended at 2017-08-25 08:13:51
 
 
 
CURRENT_TEST: rocksdb.index_merge_rocksdb2
 
--- /mnt/buildbot/build/mariadb-10.2.9/storage/rocksdb/mysql-test/rocksdb/r/index_merge_rocksdb2.result	2017-08-24 10:06:07.000000000 -0400
 
+++ /mnt/buildbot/build/mariadb-10.2.9/storage/rocksdb/mysql-test/rocksdb/r/index_merge_rocksdb2.reject	2017-08-25 08:13:51.021882038 -0400
 
@@ -251,7 +251,7 @@
 
 where t0.key1=3 or t0.key2=4;
 
 id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
 
 1	SIMPLE	t0	index_merge	i1,i2	i1,i2	4,4	NULL	2	Using union(i1,i2); Using where
 
-1	SIMPLE	t1	ref	i1	i1	4	test.t0.key1	2	
+1	SIMPLE	t1	ref	i1	i1	4	test.t0.key1	1	
 select * from t0 left join t1 on (t0.key1=t1.key1)
 
 where t0.key1=3 or t0.key2=4;
 
 key1	key2	key3	key4	key5	key6	key7	key8	key1	key2	key3	key4	key5	key6	key7	key8
 
@@ -261,7 +261,7 @@
 
 select * from t0,t1 where (t0.key1=t1.key1) and ( t0.key1=3 or t0.key2=4);
 
 id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
 
 1	SIMPLE	t0	index_merge	i1,i2	i1,i2	4,4	NULL	2	Using union(i1,i2); Using where
 
-1	SIMPLE	t1	ref	i1	i1	4	test.t0.key1	2	
+1	SIMPLE	t1	ref	i1	i1	4	test.t0.key1	1	
 explain
 
 select * from t0,t1 where (t0.key1=t1.key1) and
 
 (t0.key1=3 or t0.key2<4) and t1.key1=2;
 
 
 
mysqltest: Result content mismatch

Comment by Sergei Petrunia [ 2017-09-12 ]

Pushed the fix for the above.

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