Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-13602

rocksdb.index_merge_rocksdb2 failed in buildbot

Details

    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

          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)
          psergei Sergei Petrunia added a comment - 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)

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

          psergei Sergei Petrunia added a comment - .. 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();

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

          psergei Sergei Petrunia added a comment - .. 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 Alice Sherepa added a comment -

          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 Alice Sherepa added a comment - 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

          Pushed the fix for the above.

          psergei Sergei Petrunia added a comment - Pushed the fix for the above.

          People

            psergei Sergei Petrunia
            alice Alice Sherepa
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

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