[MDEV-13602] rocksdb.index_merge_rocksdb2 failed in buildbot - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Minor
Resolution: Fixed
Affects Version/s: 10.2(EOL)
Fix Version/s: 10.2.9
Component/s: Storage Engine - RocksDB, Tests
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;

Attachments

Activity

Ascending order - Click to sort in descending order

Sergei Petrunia added a comment - 2017-08-21 15:20

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)

Sergei Petrunia added a comment - 2017-08-21 15:20 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)

Sergei Petrunia added a comment - 2017-08-22 08:42

.. 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();

Sergei Petrunia added a comment - 2017-08-22 08:42 .. 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();

Sergei Petrunia added a comment - 2017-08-22 08:47

..
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

Sergei Petrunia added a comment - 2017-08-22 08:47 .. 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

Alice Sherepa added a comment - 2017-08-28 07:30

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

Alice Sherepa added a comment - 2017-08-28 07:30 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

Sergei Petrunia added a comment - 2017-09-12 10:33

Pushed the fix for the above.

Sergei Petrunia added a comment - 2017-09-12 10:33 Pushed the fix for the above.

People

Assignee:: Sergei Petrunia

Reporter:: Alice Sherepa

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2017-08-21 08:22

Updated:: 2017-09-12 10:33

Resolved:: 2017-08-23 15:43

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server