Playing with MySQL Source code; Adding “STOP ALL SLAVES” command

This blog post is a result of reading book.
To be clear -> “Expert MySQL” by Charles Bell -> http://www.apress.com/gp/book/9781430246596
This book explain internals of MySQL based on 5.6.x version. So relatively new and really good resource to use.

So the task is:
Chapter 8, “Extending MySQL High Availability” -> page 310, “Extending Replication”.
Where we should add new command -> “SQLCOM_STOP_SLAVES” executed on master and causing to STOP IO_THREAD on all slaves.
The basic idea is to run “STOP ALL SLAVES” on master, which in turn will appear on binary log and then it will applied on slaves.

Great 🙂
MySQL version is 5.6.32.

So, as book advice go to sql/lex.h. “We are adding the new symbol for the command. This file contains the symbol array stored in alphabetical order.”

Added:

{ "SLAVE",            SYM(SLAVE)},
  /* BEGIN CAB MODIFICATION */
  /* Reason for Modification */
  /* Add SLAVES command */
  { "SLAVES",           SYM(SLAVES)},
  /* END CAB MODIFICATION*/
  { "SLOW",             SYM(SLOW)},

Then go to sql/sql_cmd.h to add a new enumeration for the big switch. Locate enum enum_sql_command definition near the top of the file.
Added:

SQLCOM_COMMIT, SQLCOM_SAVEPOINT, SQLCOM_RELEASE_SAVEPOINT,
  /* BEGIN CAB MODIFICATION */
  /* Reason for Modification */
  /*Add SQLCOM_STOP_SLAVES enum */
  SQLCOM_SLAVE_START, SQLCOM_SLAVE_STOP, SQLCOM_STOP_SLAVES,
  /*END CAB MODIFICATION*/
  SQLCOM_BEGIN, SQLCOM_CHANGE_MASTER,

“Next we need to add a new token to be used in the new rule. Once again, the list of tokens is arranged in alphabetical order. Open the sql/sql_yacc.yy and locate the section where new tokens are defined. In this case, we need to add a definition for a token for new command. We will name it SLAVES.”
Added near line 1539/1540:

%token  SLAVE
/* BEGIN CAB MODIFICATION */
/* Reason for Modification */
/*Add SLAVES token */
%token SLAVES
/*END CAB MODIFICATION*/
%token  SLOW

“Next modify the section where the “%type” defintion resides. We need to add new token to this definition.”
Added near line 1855/1856:

slave master_def master_defs master_file_def slave_until_opts
        /* BEGIN CAB MODIFICATION */
        /* Reason for Modification */
        /* Add stop to list of NONE types */
        repair analyze check start stop checksum
        /*END CAB MODIFICATION*/
        field_list field_list_item field_spec kill column_def key_def

“Next, we add a new command definition to the list of commands so that the parser can direct control to the new rule. Notice we add a new ‘or’ condition mapping to a new rule to be evaluated.”
Added near line 2079/2080:

       | start
  /* BEGIN CAB MODIFICATION */
  /* Reason for Modification */
  /* Add stop to list of statement targets */
        | stop
  /*END CAB MODIFICATION*/
        | truncate

“Last, we will add the new rule to process the STOP ALL SLAVES command. The rule simply saves the new enumeration to the lex->sql_command attribute. This is how the code maps the result of the rule(and the processing of the command) to the big switch to a case equal to the enumeration value.”

Added near line 8114/8115:

/* BEGIN CAB MODIFICATION */
/* Reason for Modification */
/* Add rule for stop ALL SLAVES command*/
stop:
          STOP_SYM ALL SLAVES
          {
            LEX *lex= Lex;
            lex->sql_command= SQLCOM_STOP_SLAVES;
          }
        ;
/*END CAB MODIFICATION*/

“With changes to the YACC file complete, we can add a new case for the big switch to ensure the command, once captured by the parser, is directed to code to written the event to the binary log. Normally, the STOP SLAVE command is not replicated. Our code would also override this restriction. Let us add that case statement. Open the sql/sql_parse.cc

Added near line 3159/3160:

    mysql_mutex_unlock(&LOCK_active_mi);
    break;
  }

/* BEGIN CAB MODIFICATION */
/* Reason for Modification */
/* Add case statement for STOP ALL SLAVES command */
  case SQLCOM_STOP_SLAVES:
  {
    if (!lex->no_write_to_binlog)
    {
        res = write_bin_log(thd, TRUE, "STOP SLAVE IO_THREAD", 20);
    }

    break;
  }
/*END CAB MODIFICATION*/


#endif /* HAVE_REPLICATION */

  case SQLCOM_RENAME_TABLE:

“The first statement is designed to check to see if the server is able to write to the binary log. If so, we add a new log event, passing it the STOP SLAVE SQL command. Notice that we use a specific version of the STOP SLAVE command. In this case, we are stopping only IO_THREAD.”

I assume that you are familiar with compiling MySQL from source code. If not then read -> installing-mysql-from-source-cmake-issues

Go ahead and run “make” again. It will likely fail with:

Scanning dependencies of target sql
[ 54%] Building CXX object sql/CMakeFiles/sql.dir/sql_parse.cc.o
[ 54%] Building CXX object sql/CMakeFiles/sql.dir/mysqld.cc.o
In file included from /home/sh/MySQLPakcages/mysql-5.6.32/include/my_compiler.h:151:0,
                 from /home/sh/MySQLPakcages/mysql-5.6.32/include/my_global.h:473,
                 from /home/sh/MySQLPakcages/mysql-5.6.32/sql/mysqld.cc:17:
/home/sh/MySQLPakcages/mysql-5.6.32/sql/mysqld.cc: In function ‘int init_common_variables()’:
/home/sh/MySQLPakcages/mysql-5.6.32/include/my_attribute.h:38:42: error: size of array ‘compile_time_assert’ is negative
 #  define MY_ATTRIBUTE(A) __attribute__(A)
                                          ^
/home/sh/MySQLPakcages/mysql-5.6.32/include/my_global.h:377:52: note: in expansion of macro ‘MY_ATTRIBUTE’
     typedef char compile_time_assert[(X) ? 1 : -1] MY_ATTRIBUTE((unused)); \
                                                    ^
/home/sh/MySQLPakcages/mysql-5.6.32/sql/mysqld.cc:3871:3: note: in expansion of macro ‘compile_time_assert’
   compile_time_assert(sizeof(com_status_vars)/sizeof(com_status_vars[0]) - 1 ==
   ^
sql/CMakeFiles/sql.dir/build.make:3581: recipe for target 'sql/CMakeFiles/sql.dir/mysqld.cc.o' failed
make[2]: *** [sql/CMakeFiles/sql.dir/mysqld.cc.o] Error 1
CMakeFiles/Makefile2:5192: recipe for target 'sql/CMakeFiles/sql.dir/all' failed
make[1]: *** [sql/CMakeFiles/sql.dir/all] Error 2
Makefile:160: recipe for target 'all' failed
make: *** [all] Error 2

As a beginner in source code world, I suddenly found a BUG in book 🙂
After reading comments I have found something inside sql/sql_cmd.h:

/*
  When a command is added here, be sure it's also added in mysqld.cc
  in "struct show_var_st status_vars[]= {" ...
*/

So the new command should also be added inside sql/mysqld.cc. But there is no such struct show_var_st status_vars[] there. It took me some time to figure out that instead of status_vars[], command should be added into SHOW_VAR com_status_vars[]
See related report -> #83613

So edited mysqld.cc file near line 3571/3572:

{"slave_stop",           (char*) offsetof(STATUS_VAR, com_stat[(uint) SQLCOM_SLAVE_STOP]), SHOW_LONG_STATUS},
        /* BEGIN CAB MODIFICATION */
        /* Reason for Modification */
  {"stop_slaves",           (char*) offsetof(STATUS_VAR, com_stat[(uint) SQLCOM_STOP_SLAVES]), SHOW_LONG_STATUS},
        /*END CAB MODIFICATION*/

Save and recompile it will succeed. Next is to look at easy way to setup replication and test the new added command. In the book, author used tools from “MySQL Utilities”. But I have used “MySQL Sandbox” as:

make_sandbox_from_source /home/sh/MySQLPakcages/mysql-5.6.32 replication

That’s it, 1 master and 2 slaves are ready to test.

For my bad, ” stop all slaves” command failed with following assertion on master:

Version: '5.6.32-debug-log'  socket: '/tmp/mysql_sandbox23097.sock'  port: 23097  Shahriyar Rzayev's Ubuntu 16.04 MySQL-5.6.32
mysqld: /home/sh/MySQLPakcages/mysql-5.6.32/sql/protocol.cc:515: void Protocol::end_statement(): Assertion `0' failed.
14:49:07 UTC - mysqld got signal 6 ;

So ideally my statement, should return something like “Query OK”. After asking Weixiang Zhai issue fixed by adding my_ok(thd)

So the final code for sql/sql_parse.cc:

    mysql_mutex_unlock(&LOCK_active_mi);
    break;
  }

/* BEGIN CAB MODIFICATION */
/* Reason for Modification */
/* Add case statement for STOP ALL SLAVES command */
  case SQLCOM_STOP_SLAVES:
  {
    if (!lex->no_write_to_binlog)
    {
        res = write_bin_log(thd, TRUE, "STOP SLAVE IO_THREAD", 20);
    }

    if(!res)
    {
        my_ok(thd);
    }

    break;
  }
/*END CAB MODIFICATION*/


#endif /* HAVE_REPLICATION */

  case SQLCOM_RENAME_TABLE:

Recompiled and reinstalled with sandbox, the result of running new command on master:

master [localhost] {msandbox} ((none)) > stop all slaves; 
Query OK, 0 rows affected (0.00 sec)

Result on slaves:

Slave_IO_Running: No 
Slave_SQL_Running: Yes

So it works like a charm 🙂

MySQL Group Replication plugin issues with 5.7.8-rc2

Well the new things are cool to test and learn. But it is not possible every time, to have smooth testing process. if you can’t get right software on your hand.

So there are great articles about this new plugin here you can follow all of them: Group Replication Topics

I must say that, plugin available for download as source code and as for Oracle Linux 6 x86_64 from -> labs.mysql.com

So if you want to try it with MySQL 5.7.8-rc2 on Ubuntu you should compile it with MySQL. But you will not be able to compile due to well known ‘boost’ dependency -> see BUG #78600

UPDATE to BUG 78600:

Pedro Gomes clarified the reason of failed compiling process. There must not be any “spaces” between cmake options specified with -DMYSQL_SERVER_CMAKE_ARGS=””. So we have working cmake command as follows:

    cmake ..  -DMYSQL_SERVER_SRC_DIR="/home/sh/Sandboxes/mysql-5.7.8-rc" -DMYSQL_SERVER_CMAKE_ARGS="-DMYSQL_DATADIR=/opt/mysql-5.7.8-grouprepl/datadir;-DSYSCONFDIR=/opt/mysql-5.7.8-grouprepl;-DWITH_SSL=system;-DMYSQL_TCP_PORT=3307;-DMYSQL_UNIX_ADDR=/opt/mysql-5.7.8-grouprepl/mysqld.sock;-DDEFAULT_CHARSET=utf8;-DDEFAULT_COLLATION=utf8_general_ci;-DWITH_DEBUG=1;-DCOMPILATION_COMMENT='Group Replication enabled MySQL-5.7.8';-DOPTIMIZER_TRACE=1;-DWITH_ZLIB=system;-DWITH_VALGRIND=1;-DCMAKE_C_FLAGS=-DHAVE_purify;-DCMAKE_CXX_FLAGS=-DHAVE_purify;-DDOWNLOAD_BOOST=1;-DWITH_BOOST=/home/sh/Sandboxes"

But even you have Oracle Linux 6 x86_64 and even you follow topics: 1. Corosync Guide 2. Getting Started with MySQL Group Replication

You will likely get “Segmentation Fault” after running START GROUP_REPLICATION:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffc8ef2700 (LWP 3294)]
0x00007ffff625d532 in _int_malloc () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install corosynclib-1.4.7-2.el6.x86_64
(gdb) bt
#0  0x00007ffff625d532 in _int_malloc () from /lib64/libc.so.6
#1  0x00007ffff625e991 in malloc () from /lib64/libc.so.6
#2  0x00007ffff6acf0bd in operator new(unsigned long) () from /usr/lib64/libstdc++.so.6
#3  0x00007fffc8f5b2ab in Certifier::Certifier (this=0x7fffbc051d20)
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/certifier.cc:209
#4  0x00007fffc8f6bb36 in Certification_handler::initialize (this=0x7fffbc0507e0)
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/handlers/certification_handler.cc:32
#5  0x00007fffc8f634d7 in configure_pipeline (pipeline=0x7fffbc051a80, handler_list=0x7fffbc0506f0, num_handlers=3)
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/pipeline_factory.cc:143
#6  0x00007fffc8f6364d in get_pipeline (pipeline_type=<value optimized out>, pipeline=0x7fffbc051a80)
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/pipeline_factory.cc:30
#7  0x00007fffc8f554b0 in Applier_module::setup_applier_module (this=0x7fffbc051920, pipeline_type=STANDARD_GROUP_REPLICATION_PIPELINE, reset_logs=false, 
    stop_timeout=31536000, group_sidno=2)
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/applier.cc:99
#8  0x00007fffc8f63eca in configure_and_start_applier_module ()
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/plugin.cc:761
#9  0x00007fffc8f657df in plugin_group_replication_start ()
    at /export/home/pb2/build/sb_0-16452762-1441960761.59/release-0.5.0-export-8447366/BIN/BUILD/mysql-server/plugin/group_replication/src/plugin.cc:289
#10 0x00000000016927c9 in Group_replication_handler::start (this=0x378f2d0) at /home/full_datadir/mysql-5.7.8-rc/sql/rpl_group_replication.cc:56
#11 0x0000000001692b81 in group_replication_start () at /home/full_datadir/mysql-5.7.8-rc/sql/rpl_group_replication.cc:192
#12 0x000000000149739c in mysql_execute_command (thd=0x7fffbc007180) at /home/full_datadir/mysql-5.7.8-rc/sql/sql_parse.cc:3029
#13 0x000000000149e15b in mysql_parse (thd=0x7fffbc007180, parser_state=0x7fffc8ef14a0) at /home/full_datadir/mysql-5.7.8-rc/sql/sql_parse.cc:5255
#14 0x0000000001492dec in dispatch_command (thd=0x7fffbc007180, com_data=0x7fffc8ef1cd0, command=COM_QUERY)
    at /home/full_datadir/mysql-5.7.8-rc/sql/sql_parse.cc:1272
#15 0x00000000014917f3 in do_command (thd=0x7fffbc007180) at /home/full_datadir/mysql-5.7.8-rc/sql/sql_parse.cc:852
#16 0x00000000015c9042 in handle_connection (arg=0x36c1a50) at /home/full_datadir/mysql-5.7.8-rc/sql/conn_handler/connection_handler_per_thread.cc:300
#17 0x0000000001c56c41 in pfs_spawn_thread (arg=0x37d1990) at /home/full_datadir/mysql-5.7.8-rc/storage/perfschema/pfs.cc:2178
#18 0x00007ffff7bc79d1 in start_thread () from /lib64/libpthread.so.0
#19 0x00007ffff62ccb6d in clone () from /lib64/libc.so.6

For further reading refer to related fresh BUG report -> #78627

It is really cool to help community to improve Open Source projects. So go on and test by your own, report interesting things and ofcourse contact with community members. They are all open to discussion 🙂

Getting SIGABRT -> Assertion `is_binlog_empty()’ failed with MySQL 5.7.7-rc

What about inserting data to MySQL 5.7.7-rc-debug with GTID/binary log enabled. It is OK until you hit disk full condition while inserting data. It will crash on the way and likely you will lose MySQL. Error log indicates related problem:

2015-07-29T07:20:05.865708Z 2 [ERROR] InnoDB: posix_fallocate(): Failed to preallocate data for file ./sls2/sales.ibd, desired size 4194304 bytes. Operating system error number 28. Check that the disk is not full or a disk quota exceeded. Make sure the file system supports this function. Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2015-07-29T07:20:05.895529Z 2 [Warning] InnoDB: 1048576 bytes should have been written. Only 557056 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.905149Z 2 [Warning] InnoDB: 491520 bytes should have been written. Only 106496 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.906292Z 2 [Warning] InnoDB: 385024 bytes should have been written. Only 4096 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.907309Z 2 [Warning] InnoDB: 380928 bytes should have been written. Only 4096 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.908075Z 2 [Warning] InnoDB: 376832 bytes should have been written. Only 4096 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.908727Z 2 [Warning] InnoDB: 372736 bytes should have been written. Only 4096 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.909397Z 2 [Warning] InnoDB: 368640 bytes should have been written. Only 4096 bytes written. Retrying again to write the remaining bytes.
2015-07-29T07:20:05.910056Z 2 [ERROR] InnoDB: Error in system call pwrite(). The operating system error number is 28.
2015-07-29T07:20:05.910135Z 2 [ERROR] InnoDB: Error number 28 means 'No space left on device'.
2015-07-29T07:20:05.910156Z 2 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2015-07-29T07:20:05.910172Z 2 [Warning] InnoDB: Retry attempts for writing partial data failed.
2015-07-29T07:20:05.910190Z 2 [ERROR] InnoDB: Write to file ./sls2/sales.ibd failed at offset 49283072. 1048576 bytes should have been written, only 684032 were written. Check that your OS and file system support files of  this size. Check also that the disk is not full or a disk quota  exceeded.
2015-07-29T07:20:05.910220Z 2 [Warning] InnoDB: Error while writing 4194304 zeroes to ./sls2/sales.ibd starting at offset 46137344
2015-07-29T07:20:06.001777Z 2 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
mysqld: /root/mysql-5.7.7-rc/sql/binlog.cc:389: virtual void binlog_cache_data::reset(): Assertion `is_binlog_empty()' failed.

Getting: mysqld: /root/mysql-5.7.7-rc/sql/binlog.cc:389: virtual void binlog_cache_data::reset(): Assertion `is_binlog_empty()’ failed.

From GDB:

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffde31f700 (LWP 2816)]
0x00007ffff61675d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56    return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);

The next step is to examine backtrace:

(gdb) bt
#0  0x00007ffff61675d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff6168cc8 in __GI_abort () at abort.c:90
#2  0x00007ffff6160546 in __assert_fail_base (fmt=0x7ffff62b0128 "%s%s%s:%u: %s%sAssertion `%s' failed.n%n", 
    assertion=assertion@entry=0x20fdb01 "is_binlog_empty()", file=file@entry=0x20fd990 "/root/mysql-5.7.7-rc/sql/binlog.cc", line=line@entry=389, 
    function=function@entry=0x21030c0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "virtual void binlog_cache_data::reset()") at assert.c:92
#3  0x00007ffff61605f2 in __GI___assert_fail (assertion=0x20fdb01 "is_binlog_empty()", file=0x20fd990 "/root/mysql-5.7.7-rc/sql/binlog.cc", line=389, 
    function=0x21030c0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "virtual void binlog_cache_data::reset()") at assert.c:101
#4  0x000000000181ed71 in binlog_cache_data::reset (this=0x7fffb400da68) at /root/mysql-5.7.7-rc/sql/binlog.cc:389
#5  0x000000000181f091 in binlog_trx_cache_data::reset (this=0x7fffb400da68) at /root/mysql-5.7.7-rc/sql/binlog.cc:599
#6  0x000000000180776a in binlog_trx_cache_data::truncate (this=0x7fffb400da68, thd=0x7fffb4000c80, all=false) at /root/mysql-5.7.7-rc/sql/binlog.cc:1457
#7  0x00000000018089fa in MYSQL_BIN_LOG::rollback (this=0x2bd78c0 <mysql_bin_log>, thd=0x7fffb4000c80, all=false) at /root/mysql-5.7.7-rc/sql/binlog.cc:1994
#8  0x0000000000f84dfa in ha_rollback_trans (thd=0x7fffb4000c80, all=false) at /root/mysql-5.7.7-rc/sql/handler.cc:1854
#9  0x0000000001682449 in trans_rollback_stmt (thd=0x7fffb4000c80) at /root/mysql-5.7.7-rc/sql/transaction.cc:442
#10 0x000000000158e778 in mysql_execute_command (thd=0x7fffb4000c80) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:4586
#11 0x000000000158ff62 in mysql_parse (thd=0x7fffb4000c80, parser_state=0x7fffde31e5a0) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:5159
#12 0x0000000001585cf1 in dispatch_command (command=COM_QUERY, thd=0x7fffb4000c80, 
    packet=0x7fffb49fd901 "INSERT INTO `sales` VALUES (408505,'1155','40','2001-06-30 14:28:05','253','6399','34','597','0','A','','0'),(408506,'827','5','2005-05-31 14:28:05','378','1169','46','707','0','A','','0'),(408507,'16"..., packet_length=1034768) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:1249
#13 0x0000000001584b21 in do_command (thd=0x7fffb4000c80) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:835
#14 0x00000000016adcff in handle_connection (arg=0x3cbd6b0) at /root/mysql-5.7.7-rc/sql/conn_handler/connection_handler_per_thread.cc:298
#15 0x0000000001cd9905 in pfs_spawn_thread (arg=0x3bfb1f0) at /root/mysql-5.7.7-rc/storage/perfschema/pfs.cc:2147
#16 0x00007ffff7bc6df5 in start_thread (arg=0x7fffde31f700) at pthread_create.c:308
#17 0x00007ffff62281ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

For further reading and finding bt full output refer to related BUG report -> #76825

Announced – MySQL 5.7 Community Contributor Award Program 2015!

I am glad to share this post with community. It is really great story for a young guy to be among experts!

Today Lenka Kasparova announced results of: MySQL 5.7 Community Contributor Award Program 2015!

Awarded as:

Shahriyar Rzayev, the Azerbaijan MySQL User Group leader for reproducing bugs in MySQL 5.7

See my MySQL BUG database activity -> Reporter: Shahriyar Rzayev

Also there is a gift from MySQL Community team:

community_contributor2

community_contributor1

Altering tablespace of table – new in MySQL 5.7

Dear community, maybe you have already tested, there are new added features in MySQL 5.7. See previous post -> About 5.7.7-rc BUGs

“General Tablespace” feature -> From now you can place tables to separate tablespaces. Prior, on our hands there were only “System TableSpace” and “InnoDB file per table” options. Today’s topic is altering table to use this “General Tablespace”.

Our sample table structure:

mysql> show create table t1;

    | Table | Create Table 
    | t1    | CREATE TABLE `t1` (
      `id` int(11) DEFAULT NULL,
      `c1` varchar(85) DEFAULT NULL
    ) /*!50100 TABLESPACE innodb_file_per_table */ ENGINE=InnoDB DEFAULT CHARSET=utf8 

Note that there is a comment about tablespace of our table -> /*!50100 TABLESPACE innodb_file_per_table */. So our table has very own .ibd file as usual. Let’s create a separate tablespace:

mysql> CREATE TABLESPACE `ts1` ADD DATAFILE 'ts1.ibd' Engine=InnoDB;
Query OK, 0 rows affected (0.03 sec)

If you do not specify path for ‘ts1.ibd’ file it will be created in “datadir” by default. Let’s note the initial size of this file:

[root@centos7_vm datadir]# ls -ltr | grep ts1.ibd
-rw-r-----. 1 root  root     65536 Jul 23 16:12 ts1.ibd

Now it is time to alter table:

mysql> alter table t1 tablespace ts1;
Query OK, 0 rows affected (1 min 5.41 sec)
Records: 0  Duplicates: 0  Warnings: 0

The create statement of table will be affected too:

    mysql> show create table t1;
    | Table | Create Table                                                  
    | t1    | CREATE TABLE `t1` (
      `id` int(11) DEFAULT NULL,
      `c1` varchar(85) DEFAULT NULL
    ) /*!50100 TABLESPACE ts1 */ ENGINE=InnoDB DEFAULT CHARSET=utf8 |

NOTE: /*!50100 TABLESPACE ts1 */

Write down size of ‘ts1.ibd’ file again:

[root@centos7_vm datadir]# ls -ltr | grep ts1.ibd
-rw-r-----. 1 root  root  155189248 Jul 23 16:16 ts1.ibd

155189248 -> ts1.ibd

Let’s try to alter table with same tablespace file (2nd time):

mysql> alter table t1 tablespace ts1;
Query OK, 0 rows affected (1 min 5.05 sec)
Records: 0  Duplicates: 0  Warnings: 0

Pay attention to ts1.ibd file size:

[root@centos7_vm datadir]# ls -ltr | grep ts1.ibd
-rw-r-----. 1 root  root  301989888 Jul 23 16:18 ts1.ibd

301989888 -> ts1.ibd

The tablespace file is increased by same table twice…

Also checkout related BUG report -> #77814

Testing MySQL 5.7.7-rc with memory and disc full conditions

With MySQL 5.7 there will be many improvements and changes. The most valuable ones are:

1. “General Tablespace” feature -> From now you can place tables to separate tablespaces. Prior, on our hands there were only “System TableSpace” and “InnoDB file per table” options.

Check for further reading: General Tablespaces Create statement: Create TableSpace

2. Resizing InnoDB Buffer Pool online -> for changing innodb_buffer_pool_size variable restart is required prior to MySQL 5.7, from now we can change buffer pool size without restart dynamically. Read Documentation -> innodb-buffer-pool-online-resize

To break this new things, we need to create some conditions where Memory or Disc will be full. Firstly let’s try to resize innodb buffer pool size without having sufficient memory.

Note: MySQL installation: debug enabled

Started MySQL as:

(gdb) run --defaults-file=/opt/mysql/my.cnf --basedir=/opt/mysql --datadir=/opt/mysql/datadir --plugin-dir=/opt/mysql/lib/plugin --user=mysql --log-error=/opt/mysql/datadir/centos7-1_vm.err --pid-file=/opt/mysql/datadir/mysqld-new.pid --socket=/opt/mysql/datadir/mysqld-new.sock --port=3306

Then try to resize:

mysql> SET @@GLOBAL.innodb_buffer_pool_size=9556544565345346;
Query OK, 0 rows affected, 2 warnings (0.00 sec)

After few attempts it will stuck with SIGABRT signal:

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffb77f6700 (LWP 17145)]
0x00007ffff61675d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56    return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);

(gdb) bt
#0  0x00007ffff61675d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff6168cc8 in __GI_abort () at abort.c:90
#2  0x0000000001adbe0f in ut_dbg_assertion_failed (expr=0x0, file=0x21956d8 "/root/mysql-5.7.7-rc/storage/innobase/ut/ut0ut.cc", line=906)
at /root/mysql-5.7.7-rc/storage/innobase/ut/ut0dbg.cc:67
#3  0x0000000001ae123e in ib::fatal::~fatal (this=0x7fffb77f49e0, __in_chrg=<optimized out>) at /root/mysql-5.7.7-rc/storage/innobase/ut/ut0ut.cc:906
#4  0x00000000018f18e8 in ut_allocator<unsigned char>::allocate (this=0x7fffb77f4ba0, n_elements=14238670808, hint=0x0, 
    file=0x21cbb10 "/root/mysql-5.7.7-rc/storage/innobase/ha/hash0hash.cc", set_to_zero=false, throw_on_error=false)
    at /root/mysql-5.7.7-rc/storage/innobase/include/ut0new.h:328
#5  0x0000000001bed775 in hash0_create (n=1756528640) at /root/mysql-5.7.7-rc/storage/innobase/ha/hash0hash.cc:284
#6  0x000000000194769d in lock_sys_resize (n_cells=1756528640) at /root/mysql-5.7.7-rc/storage/innobase/lock/lock0lock.cc:478
#7  0x0000000001b3dce1 in buf_pool_resize () at /root/mysql-5.7.7-rc/storage/innobase/buf/buf0buf.cc:2669
#8  0x0000000001b3e0f5 in buf_resize_thread (arg=0x0) at /root/mysql-5.7.7-rc/storage/innobase/buf/buf0buf.cc:2749
#9  0x00007ffff7bc6df5 in start_thread (arg=0x7fffb77f6700) at pthread_create.c:308
#10 0x00007ffff62281ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

See Related verified BUG report -> #77564

How about creating “General Tablespace” if there is no free disk space? Again started with:

[root@centos7_vm ~]# gdb /opt/mysql/bin/mysqld
(gdb) run --defaults-file=/opt/mysql/my.cnf --basedir=/opt/mysql --datadir=/opt/mysql/datadir --plugin-dir=/opt/mysql/lib/plugin --user=mysql --log-error=/opt/mysql/datadir/centos7_vm.err --pid-file=/opt/mysql/datadir/mysqld-new.pid --socket=/opt/mysql/datadir/mysqld-new.sock --port=3306

Try to run create tablespace:

mysql> CREATE TABLESPACE `ts2` ADD DATAFILE 'ts2.ibd' Engine=InnoDB;

In error log there is some mention about full disk:

2015-06-30T05:34:41.379790Z 2 [ERROR] InnoDB: Encountered a problem with file ./ts2.ibd
2015-06-30T05:34:41.379865Z 2 [ERROR] InnoDB: Disk is full. Try to clean the disk to free space.
2015-06-30T05:34:41.379910Z 2 [ERROR] InnoDB: Operating system error number 28 in a file operation.
2015-06-30T05:34:41.379937Z 2 [ERROR] InnoDB: Error number 28 means 'No space left on device'.
2015-06-30T05:34:41.379952Z 2 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2015-06-30T05:34:41.393247Z 2 [ERROR] InnoDB: Cannot create file './ts2.ibd'

From GDB we will see SIGSEGV signal:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffddf7e700 (LWP 2787)]
__strnlen_sse2 () at ../sysdeps/x86_64/strnlen.S:34
34      pcmpeqb (%rdi), %xmm2

    (gdb) bt
#0  __strnlen_sse2 () at ../sysdeps/x86_64/strnlen.S:34
#1  0x0000000001dc18f2 in process_str_arg (cs=0x2ba3ea0 <my_charset_utf8_general_ci>, to=0x7fffddf7bfdb "02", end=0x7fffddf7c1cf "", width=192, 
    par=0x1 <Address 0x1 out of bounds>, print_type=0) at /root/mysql-5.7.7-rc/strings/my_vsnprintf.c:194
#2  0x0000000001dc32e6 in my_vsnprintf_ex (cs=0x2ba3ea0 <my_charset_utf8_general_ci>, to=0x7fffddf7bfdb "02", n=512, fmt=0x2d32a12 "s' is full", 
    ap=0x7fffddf7c1d0) at /root/mysql-5.7.7-rc/strings/my_vsnprintf.c:607
#3  0x000000000189d0e9 in my_error (nr=135, MyFlags=0) at /root/mysql-5.7.7-rc/mysys/my_error.c:206
    #4  0x0000000001622428 in mysql_alter_tablespace (thd=0x7fffcc000e20, ts_info=0x7fffcc022080) at /root/mysql-5.7.7-rc/sql/sql_tablespace.cc:191
#5  0x000000000158e104 in mysql_execute_command (thd=0x7fffcc000e20) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:4432
#6  0x000000000158ff62 in mysql_parse (thd=0x7fffcc000e20, parser_state=0x7fffddf7d5a0) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:5159
#7  0x0000000001585cf1 in dispatch_command (command=COM_QUERY, thd=0x7fffcc000e20, 
packet=0x7fffcc006f71 "CREATE TABLESPACE `ts2` ADD DATAFILE 'ts2.ibd' Engine=InnoDB", packet_length=60) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:1249
#8  0x0000000001584b21 in do_command (thd=0x7fffcc000e20) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:835
#9  0x00000000016adcff in handle_connection (arg=0x3c92060) at /root/mysql-5.7.7-rc/sql/conn_handler/connection_handler_per_thread.cc:298
#10 0x0000000001cd9905 in pfs_spawn_thread (arg=0x3b4dcd0) at /root/mysql-5.7.7-rc/storage/perfschema/pfs.cc:2147
#11 0x00007ffff7bc6df5 in start_thread (arg=0x7fffddf7e700) at pthread_create.c:308
#12 0x00007ffff62281ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Related BUG report -> #77556

If you have you own test cases, please share it.

MySQL Optimizer Tracer usage case with count(*)

What is Optimizer Trace? After reading topic about Optimizer Tracer by [Morgan Tocker][1] decided to test it. From [Optimizer Trace and EXPLAIN FORMAT=JSON in 5.7][2]: Optimizer trace is a new diagnostic tool introduced in MySQL 5.6 to show how the optimizer is working internally. It is similar to EXPLAIN, with a few notable differences: It doesn’t just show the intended execution plan, it shows the alternative choices. You enable the optimizer trace, then you run the actual query. It is far more verbose in its output. For understanding goal of article please read previous one about related verified optimizer BUG: [Playing with count() optimizer work][3] ** We have 2 queries: **select count() from sales; select count(*) from sales where sales_id > 0; Firstly let’s get explain plan for query with JSON format and as regular:

       -- JSON 
          mysql> explain format=json select count(*) from sales; |
          { "query_block": 
          { "select_id": 1, 
          "table": { "table_name": "sales", 
                     "access_type":  "index", 
                     "key": "sales_cust_idx", 
                     "used_key_parts": [ "CUSTOMER_ID" ] 
                    /*  used_key_parts */, 
                    "key_length": "4", 
                    "rows": 2489938, 
                    "filtered": 100,
                     "using_index": true }  
            /* table */ } 
           /* query_block */ } 

        mysql> explain select count(*) from salesG 
        *************************** 1. row *************************** 
        id: 1 
        select_type: SIMPLE 
        table: sales 
        type: index 
        possible_keys: NULL 
        key: sales_cust_idx 
        key_len: 4 
        ref: NULL 
        rows: 2489938 
        Extra: Using index 1 row in set (0.00 sec) 

Second query:

       -- JSON  
       mysql> explain format=json select count(*) from sales where sales_id > 0G         *************************** 1. row *************************** 
    EXPLAIN: 
    { "query_block": 
    { "select_id": 1, 
    "table": 
    { "table_name": "sales", 
      "access_type": "range",
      "possible_keys": [ "PRIMARY" ], "key": "PRIMARY", 
      "used_key_parts": [ "SALES_ID" ], "key_length": "4", 
      "rows": 1244969, 
      "filtered": 100, 
      "using_index": true, 
     "attached_condition": "(`sales`.`sales`.`SALES_ID` > 0)" } } } 


     mysql> explain select count(*) from sales where sales_id > 0G 
     *************************** 1. row *************************** 
     id: 1 
     select_type: SIMPLE 
     table: sales 
     type: range 
     possible_keys: PRIMARY 
     key: PRIMARY 
     key_len: 4 
     ref: NULL 
     rows: 1244969 
     Extra: Using where; Using index 1 row in set (0.00 sec)  

From Explain plan it is obvious that, first query will use “Index Scan”, second will use “Range Scan + Index”. First query will use, sales_cust_idx in customer_id column, second query will use primary key in sales_id column. From first view, there now difference between queries, but optimizer estimates half of rows when attaching sales_id > 0 condition. See related BUG: [#68814][4] Now let’s examine problem with Optimizer Tracer. So before running query you should enable optimizer trace:

      SET OPTIMIZER_TRACE="enabled=on",END_MARKERS_IN_JSON=on;
      SET OPTIMIZER_TRACE_MAX_MEM_SIZE=1000000; 

After run first query:

      mysql> select count(*) from sales; 
      +----------+ 
      | count(*) |
      +----------+
      | 2500003 |
      +----------+ 
     1 row in set (0.58 sec) 

Query to OPTIMIZER_TRACE table from information_schema:

     mysql> select query, trace from INFORMATION_SCHEMA.OPTIMIZER_TRACE;
     select count(*) from sales | 
    { "steps": 
   [ { "join_preparation": 
    { "select#": 1, 
    "steps": [ { "expanded_query": "/* select#1 */ select count(0) AS `count(*)` from `sales`" } ] /* steps */ }
    /* join_preparation */ },
    { "join_optimization": 
       { "select#": 1, 
         "steps": [ { "table_dependencies": [ { "table": "`sales`", "row_may_be_null": false, "map_bit": 0, "depends_on_map_bits": [ ] 
    /* depends_on_map_bits */ } ] 
    /* table_dependencies */ }, 
      { "rows_estimation": 
           [ { "table": "`sales`", "table_scan": { "rows": 2489938, "cost": 10347 }
          /* table_scan */ } ] 
          /* rows_estimation */ }, 
           { "considered_execution_plans": [ { "plan_prefix": [ ] 
           /* plan_prefix */,
           "table": "`sales`", 
           "best_access_path": { "considered_access_paths": [ { "access_type": "scan", "rows": 2.49e6, "cost": 508335, "chosen": true } ] 
          /* considered_access_paths */ } 
          /* best_access_path */, 
         "cost_for_plan": 508335,
         "rows_for_plan": 2.49e6,
         "chosen": true } ]
         /* considered_execution_plans */ },
        { "attaching_conditions_to_tables": { "original_condition": null,  "attached_conditions_computation": [ ] 
        /* attached_conditions_computation */,
       "attached_conditions_summary": [ { "table": "`sales`", "attached": null } ] 
        /* attached_conditions_summary */ } 
        /* attaching_conditions_to_tables */ },
       { "refine_plan": [ { "table": "`sales`", "access_type": "index_scan" } ] 
        /* refine_plan */ } ] 
        /* steps */ } 
        /* join_optimization */ },
        { "join_execution": { "select#": 1, "steps": [ ] 
        /* steps */ } 
        /* join_execution */ } ] 
        /* steps */ 

Interesting part for query 1 is -> “cost_for_plan”: 508335, “rows_for_plan”: 2.49e6, “chosen”: true Cost is 508335, rows for plan is 2.49e6 = 2490000 rows, is roughly equal to explain plan estimation.
Now second query:

     mysql> select count(*) from sales where sales_id > 0;
     +----------+ 
     | count(*) |
     +----------+ 
     | 2500003 |
     +----------+ 1 row in set (1.18 sec) 

Query to OPTIMIZER_TRACE:

     mysql> select query, trace from INFORMATION_SCHEMA.OPTIMIZER_TRACE; 
     select count(*) from sales where sales_id > 0 | 
     { "steps": [ { "join_preparation": 
        { "select#": 1, 
          "steps": [ { "expanded_query": "/* select#1 */ select count(0) AS `count(*)` from `sales` where (`sales`.`SALES_ID` > 0)" } ] 
        /* steps */ } 
        /* join_preparation */ },
       { "join_optimization": 
          { "select#": 1, 
            "steps": [ { "condition_processing": { "condition": "WHERE", "original_condition": "(`sales`.`SALES_ID` > 0)", "steps": [ { "transformation": "equality_propagation", 
           "resulting_condition": "(`sales`.`SALES_ID` > 0)" }, 
          { "transformation": "constant_propagation", "resulting_condition": "(`sales`.`SALES_ID` > 0)" }, 
          { "transformation": "trivial_condition_removal", "resulting_condition": "(`sales`.`SALES_ID` > 0)" } ] 
         /* steps */ } 
         /* condition_processing */ }, 
        { "table_dependencies": [ { "table": "`sales`", "row_may_be_null": false, "map_bit": 0, "depends_on_map_bits": [ ] 
        /* depends_on_map_bits */ } ] 
        /* table_dependencies */ }, 
       { "ref_optimizer_key_uses": [ ] 
        /* ref_optimizer_key_uses */ },
       { "rows_estimation": [ { "table": "`sales`", "range_analysis": { "table_scan": {  "rows": 2489938, "cost": 508337 } 
       /* table_scan */, 
       "potential_range_indices": [ { "index": "PRIMARY", "usable": true, "key_parts": [ "SALES_ID" ] 
      /* key_parts */ }, 
      { "index": "sales_cust_idx", "usable": false, "cause": "not_applicable" } ] 
      /* potential_range_indices */,
     "best_covering_index_scan": { "index": "sales_cust_idx", "cost": 500418, "chosen": true } 
      /* best_covering_index_scan */,
      "setup_range_conditions": [ ] 
      /* setup_range_conditions */, 
      "group_index_range": { "chosen": false, "cause": "not_group_by_or_distinct" } 
      /* group_index_range */, 
      "analyzing_range_alternatives": { "range_scan_alternatives": [ { "index": "PRIMARY", "ranges": [ "0 < SALES_ID" ] 
     /* ranges */, 
     "index_dives_for_eq_ranges": true, 
     "rowid_ordered": true, 
     "using_mrr": false, "index_only": true, "rows": 1244969, "cost": 251364, "chosen": true } ] 
    /* range_scan_alternatives */,
   "analyzing_roworder_intersect": { "usable": false, "cause": "too_few_roworder_scans" }  /* analyzing_roworder_intersect */ } 
    /* analyzing_range_alternatives */,
   "chosen_range_access_summary": { "range_access_plan": { "type": "range_scan", "index": "PRIMARY", "rows": 1244969, "ranges": [ "0 < SALES_ID" ] 
   /* ranges */ } 
   /* range_access_plan */, 
   "rows_for_plan": 1244969, "cost_for_plan": 251364, "chosen": true } 
   /* chosen_range_access_summary */ } 
   /* range_analysis */ } ] 
   /* rows_estimation */ },
    { "considered_execution_plans": [ { "plan_prefix": [ ] /* plan_prefix */, "table": "`sales`", "best_access_path": { "considered_access_paths": [ { "access_type": "range", "rows": 1.24e6, "cost": 500357, "chosen": true } ] 
    /* considered_access_paths */ } 
    /* best_access_path */, 
    "cost_for_plan": 500357, "rows_for_plan": 1.24e6, "chosen": true } ] 
    /* considered_execution_plans */ },
    { "attaching_conditions_to_tables": { "original_condition": "(`sales`.`SALES_ID` > 0)", "attached_conditions_computation": [ ] 
   /* attached_conditions_computation */,
   "attached_conditions_summary": [ { "table": "`sales`", "attached": "(`sales`.`SALES_ID` > 0)" } ] 
   /* attached_conditions_summary */ } 
   /* attaching_conditions_to_tables */ }, 
   { "refine_plan": [ { "table": "`sales`", "access_type": "range" } ] /* refine_plan */ } ] 
   /* steps */ } 
   /* join_optimization */ }, 
  { "join_execution": { "select#": 1, "steps": [ ] /* steps */ } /* join_execution */ } ] /* steps */ 

It is much more complicated with second query and due to lacking documentation for all output, i am looking for explanations from experts.
First thing is, it says in “potential_range_indices” that “index”: “sales_cust_index” is not usable:

      "potential_range_indices": 
      [ { "index": "PRIMARY", "usable": true, "key_parts": [ "SALES_ID" ] 
      /* key_parts */ },
      { "index": "sales_cust_idx", "usable": false, "cause": "not_applicable" } ] 

But in “best_covering_index_scan”, “index”: “sales_cust_idx” is marked as “chosen”:true

       "best_covering_index_scan": { "index": "sales_cust_idx", "cost": 500418, "chosen": true } 

Second thing is, in “range_scan_alternatives” and,

        "analyzing_range_alternatives": 
        { "range_scan_alternatives": [ { "index": "PRIMARY", "ranges": [ "0 < SALES_ID" ]  
        /* ranges */, 
       "index_dives_for_eq_ranges": true, "rowid_ordered": true, "using_mrr": false, "index_only": true, "rows": 1244969, "cost": 251364, "chosen": true } 

in “chosen_range_access_summary”, “rows_for_plan” is 1244969 and “cost_for_plan” is 251364

       "chosen_range_access_summary": 
       { "range_access_plan": 
        { "type": "range_scan", "index": "PRIMARY", "rows": 1244969, "ranges": [ "0 < SALES_ID" ] 
         /* ranges */ } 
         /* range_access_plan */, 
        "rows_for_plan": 1244969, "cost_for_plan": 251364, "chosen": true } 

But for final “best_access_path” “cost_for_plan” is increased to 500357 and “rows_for_plan” is 1.24e6 = 1240000:

       "best_access_path": { "considered_access_paths": [ { "access_type": "range", "rows": 1.24e6, "cost": 500357, "chosen": true } ] 
       /* considered_access_paths */ } 
       /* best_access_path */, 
       "cost_for_plan": 500357, "rows_for_plan": 1.24e6, "chosen": true }

Third thing is that, sales_id > 0 is rewritten to 0 < sales_id

      "ranges": [ "0 < SALES_ID" ] 

*** After explanations from community this article will be updated ***

http://www.tocker.ca/
http://www.tocker.ca/2015/05/25/optimizer-trace-and-explain-formatjson-in-5-7.html
https://mysql.az/playing-with-count-optimizer-work/
http://bugs.mysql.com/bug.php?id=68814