The origin of “Assertion Failed” errors in MySQL

Recently, we have discussed BUGs with our local community members. Where the half off people said that, they have seen “Assertion Failure” errors in error log. And the question was what is this at all?

In general “assert” is a code portion put by developer to handle certain things.

Well, i am not a core MySQL developer and my C/C++ knowledge is limited to simple calculator 🙂 But i will try to explain where all these “Assertion Failure” errors come up.
The exact reason of failing Assertion/crash should be known by core developers. I know how to crash, they know how to fix. You help developers to reproduce a crash filling a bug report, by uploading test cases or maybe the core dump, backtrace etc.
Say, for eg, if you try to create a view after getting “full disk” error you will crash MySQL. See related BUG report -> #76827

While testing full disk conditions, if we try to import huge dump, we will see:

2015-04-24 09:07:52 7faf8bcab700 InnoDB: Error: Write to file ./sales/sales.ibd failed at offset 247463936.
InnoDB: 1048576 bytes should have been written, only 299008 were written.
InnoDB: Operating system error number 11.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 11 means 'Resource temporarily unavailable'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2015-04-24 09:07:52 28213 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 09:08:13 28213 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 09:08:27 28213 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full

After detecting Full Disk error, if you try to create view:

mysql> create view f as select * from sales;
ERROR 2013 (HY000): Lost connection to MySQL server during query

From error log:

mysqld: /root/mysql-5.6.24/mysys/mf_iocache.c:1799: my_b_flush_io_cache: Assertion `info->end_of_file == inline_mysql_file_tell("/root/mysql-5.6.24/mysys/mf_iocache.c", 1799, info->file, (myf) (0))' failed.
13:13:48 UTC - mysqld got signal 6 ;

So that’s all, from error log it obvious that there is a file named: /root/mysql-5.6.24/mysys/mf_iocache.c and on line 1799 there is an assert inside my_b_flush_io_cache function.
If you go ahead and open up this line you will see something like:

else
     {
        info->end_of_file+=(info->write_pos-info->append_read_pos);
       DBUG_ASSERT(info->end_of_file == mysql_file_tell(info->file, MYF(0)));
     }

For now let’s pause here and introduce new things, such as what is “Optimized”, “Debug” and “Valgrind” builds of MySQL. Please watch this wonderfull video recorded by QA expert Roel Van de Paar after you will learn about newly intoduced topics. -> MySQL QA Episode 11

In general the “Optimized” MySQL is a GA version of MySQL released by vendors. It is production ready and it is working as fast as possible. So there is no “unnecessary” codes inside this build.
The “Debug” build is for debugging purpose and there is a DEBUG instrumentation code portions inside source code.
in “Valgrind” build, there are “Debug” + “Valgrind” instrumentation codes inside source code.

So above we saw DBUG_ASSERT(info->end_of_file == mysql_file_tell(info->file, MYF(0))); -> It means that this “assert” code will be shown only with “Debug” build. You will not see this code in “Optimized” MySQL source code.

Ok, let’s go on. As we have mentioned “assert” code is written by developer to handle several conditions. It might be for eg, developer decides that, if variable named num will be equal to NULL something weird is happened, terminate the program at that point.

Let’s write a simple code with our very own “assert”. Here is our assert_test.c file:

#include <stdio.h>      /* printf */
#include <assert.h>     /* assert */

void check_number(int myInt) {
  assert (myInt!=NULL);
  printf ("%dn",myInt);
}

int main ()
{
  int a=10;
  int b = NULL;

  check_number (a);
  check_number (b);

  return 0;
}

We have put an “assert” ensuring that myInt will never be “NULL”.
Compile source code:

    gcc assert_test.c -o assert_test

And run:

sh@shrzayev:~$ ./assert_test
10
assert_test: assert_test.c:5: check_number: Assertion `myInt!=((void *)0)' failed.
Aborted (core dumped)

So as you see, the same error comes up with our little code.
We have assert_test.c file and inside check_number function at line 5 there is an “assert” code which is failed.

I Hope have explained this point. Thank you for reading.

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.

About Azerbaijan MUG 1st meetup

Yesterday in 14 May at 7 PM we had our first meetup, thanks for great interest from our local community. It is also noted by Oracle: MySQL User Group meeting Azerbaijan
I spoke about contributing MySQL community and project, such ways as finding and reporting bugs, testing beta or RC versions, writing articles, giving tips, feedbacks so forth.
Also there was a note about code contribution paths, what is patch , how to get source code, what is GPL, OCA agreement etc.
Below i will put photos from meeting:
IMG_2942

IMG_2944

IMG_2950

IMG_2951

IMG_2952

IMG_2953

IMG_2954

IMG_2955

IMG_2956

IMG_2957

Partial table recovery from physical backup

In previous topic, we have covered “Transportable Tablespace” concept by copying and importing table’s tablespace to remote server. See -> Copying Tablespaces to Remote Server The idea is copying tablespace file to remote server, in remote server you must create identical database names and table names manually, then you should discard new table’s tablespace file and import new copied one. To achieve this you must have running MySQL version >= 5.6, innodb_file_per_table=1 and you must know “CREATE statement” of table. Let’s to change our test condition. Assume that, you have MySQL server and you have taken physical backup of your server (you can use Percona XtraBackup, cold backup for eg.). But one of the wonderful day somebody deleted all table data (say -> delete from table_name). In fact your table at this moment exists(.frm and .ibd), you can easily discard table’s tablespace and import tablespace from backup folder. But if table is dropped and you don’t know the create of table. Or even database is dropped. Our path will differ from previous one: *1. Create dropped database manually. 2. Create dropped table by extracting table’s create statement from .frm file which is in backed up directory. To extract table create statement from .frm file you can use **mysqlfrm tool from MySQL Utilities. 3. Discard table’s tablespace (ALTER TABLE t DISCARD TABLESPACE;) 4. Copy .ibd file from backup directory to MySQL’s datadir database directory 5. Import copied back tablespace file.(ALTER TABLE t IMPORT TABLESPACE;)*** You can also read about this concept from documentation -> tablespace-copying I have automatized this process adding table create statement extracting functionality to MySQL-AutoXtraBackup project as –partial recovery option. Here is a demo usage video:

If you tested and found issues, please report it to improve this opensource project.

Error reading GTIDs from binary log: -1

Wonder how MySQL Slave server will act, when disk full condition occurs? Before in our articles we use only single MySQL server. Now think about replication topology, where slave server has problem with full partition. Firstly we will enable Binary Log/GTID on Slave side and will ensure that the changes also applied to binary log on Slave side:

      # BINARY LOGGING # 
      server_id = 2 
      log_bin = /opt/mysql/datadir/mysql-bin 
      log_bin_index = /opt/mysql/datadir/mysql-bin 
      expire_logs_days = 14 
      sync_binlog = 1 
      binlog_format = row 
      relay_log = /opt/mysql/datadir/mysql-relay-bin 
      log_slave_updates = 1 
      read_only = 1 
      gtid-mode = on 
      enforce-gtid-consistency = true 
      master-info-repository = TABLE 
      relay-log-info-repository = TABLE 
      slave-parallel-workers = 15 
      binlog-checksum = CRC32 
      master-verify-checksum = 1 
      slave-sql-verify-checksum = 1 
      binlog-rows-query-log_events = 1 

When disk full condition comes up, error log will be filled as follows:

     2015-05-01 04:42:10 2033 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000002' at position 557, relay log '/opt/mysql/datadir/mysql-relay-bin.000001' position: 4 2015-05-01 04:50:50 7f3b79865700 
     InnoDB: Error: Write to file ./test1/sales.ibd failed at offset 184549376. 
     InnoDB: 1048576 bytes should have been written, only 688128 were written. 
     InnoDB: Operating system error number 0. 
     InnoDB: Check that your OS and file system support files of this size. 
     InnoDB: Check also that the disk is not full or a disk quota exceeded. 
     InnoDB: Error number 0 means 'Success'. 
     InnoDB: Some operating system error numbers are described at 
     InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html 2015-05-01 04:50:51 2033 
     [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 2015-05-01 04:50:51 2033 
     [ERROR] Slave SQL: Worker 14 failed executing transaction '328e26e9-ea51-11e4-8023-080027745404:242' at master log mysql-bin.000002, end_log_pos 275717680; Could not execute Write_rows event on table test1.sales; 
      The table 'sales' is full, 
      Error_code: 1114; handler error HA_ERR_RECORD_FILE_FULL; the event's master log mysql-bin.000002, end_log_pos 275717680, 
     Error_code: 1114 2015-05-01 04:50:51 2033 
     [Warning] Slave SQL: ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries  could lead to problems. In such cases you have to examine your data (see documentation for details). 
    Error_code: 1756 2015-05-01 04:50:51 2033 
    [Note] Error reading relay log event: slave SQL thread was killed 2015-05-01 04:50:51 2033 
    [Warning] Slave SQL: ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details). 
   Error_code: 1756 2015-05-01 04:50:51 2033 
   [Warning] Slave SQL: ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details). Error_code: 1756 2015-05-01 04:50:52 2033 
   [Warning] Disk is full writing '/opt/mysql/datadir/mysql-relay-bin.000003' (Errcode: 28 - No space left on device). Waiting for someone to free space... 

Interesting thing is OS error number which is equal to 0. And 0 equals to “success”. After if you try disable binary log/GTID and store only relay-log information in my.cnf as follows:

    # BINARY LOGGING # # 
    server_id = 2 
    #log_bin = /opt/mysql/datadir/mysql-bin 
    #log_bin_index = /opt/mysql/datadir/mysql-bin 
    #expire_logs_days = 14 
    #sync_binlog = 1 
    #binlog_format = row 
    relay_log = /opt/mysql/datadir/mysql-relay-bin 
    #log_slave_updates = 1 
    read_only = 1 
    #gtid-mode = on 
    #enforce-gtid-consistency = true 
    master-info-repository = TABLE 
    relay-log-info-repository = TABLE 
    #slave-parallel-workers = 15 
    #binlog-checksum = CRC32 
    #master-verify-checksum = 1 
    #slave-sql-verify-checksum = 1 
    #binlog-rows-query-log_events = 1 

If you try to start there will be some interesting errors in error log:

2015-05-01 05:05:09 2698 [ERROR] /opt/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. 
2015-05-01 05:05:14 2698 [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 8178, event_type: 30 
2015-05-01 05:05:14 2698 [Warning] Error reading GTIDs from binary log: -1 
2015-05-01 05:05:15 2698 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2015-05-01 05:05:15 2698 [Note] Slave I/O thread: connected to master 'repl@192.168.1.164:3307',replication started in log 'mysql-bin.000002' at position 204643802 
2015-05-01 05:05:16 2698 [ERROR] Slave I/O: The slave IO thread stops because the master has @@GLOBAL.GTID_MODE ON and this server has @@GLOBAL.GTID_MODE OFF, Error_code: 1593 
2015-05-01 05:05:16 2698 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000002', position 204643802 
2015-05-01 05:05:16 2698 [Note] Event Scheduler: Loaded 0 events 
2015-05-01 05:05:16 2698 [Note] /opt/mysql/bin/mysqld: ready for connections. Version: '5.6.24-debug' socket: '/opt/mysql/datadir/mysqld-new.sock' port: 3307 Shahriyar Rzayev's MySQL 
2015-05-01 05:05:16 2698 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000002' at position 274388137, relay log '/opt/mysql/datadir/mysql-relay-bin.000003' position: 274387894 
2015-05-01 05:05:16 2698 [ERROR] Slave SQL: @@SESSION.GTID_NEXT cannot be set to UUID:NUMBER when @@GLOBAL.GTID_MODE = OFF. Error_code: 1781 
2015-05-01 05:05:16 2698 [Warning] Slave: @@SESSION.GTID_NEXT cannot be set to UUID:NUMBER when @@GLOBAL.GTID_MODE = OFF. Error_code: 1781 
2015-05-01 05:05:16 2698 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000002' position 274388137 [/code] Errors about disabled GTID is normal and it must be here as usual. But must interesting is:  [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 8178, event_type: 30           
[Warning] Error reading GTIDs from binary log: -1  

[Warning] Error reading GTIDs from binary log: -1. Related BUG report -> #72437 If you have another issue path related to slave server’s disk usage, will be interesting to hear from you.

Testing MySQL with “read-only” filesystem

From previous articles about “disk full” conditions, you have some taste of testing MySQL with such approach:

1. Testing Disk Full Conditions

2. Using GDB, investigating segmentation fault in MySQL

But there is still untouched topic, about read-only mounted file system and how MySQL will act in such condition. In real life, i have encountered such situation that something happened with Linux server and file system suddenly goes to read-only mode.

Buffer I/O error on device sdb1, logical block 1769961 lost page write due to I/O error on sdb1 sd 0:0:1:0: timing out command, waited 360s sd 0:0:1:0: Unhandled error code sd 0:0:1:0: SCSI error: return code = 0x06000008 Result: hostbyte=DID_OK driverbyte=DRIVER_TIMEOUT,SUGGEST_OK mptscsih: ioc0: attempting task abort! (sc=ffff8100b629a6c0) sd 0:0:1:0: command: Write(10): 2a 00 00 d8 15 17 00 04 00 00 mptscsih: ioc0: task abort: SUCCESS (rv=2002) (sc=ffff8100b629a6c0) Aborting journal on device sdb1. 
ext3_abort called. EXT3-fs error (device sdb1): ext3_journal_start_sb: Detected aborted journal Remounting filesystem read-only __journal_remove_journal_head: freeing b_committed_data EXT3-fs error (device sdb1) in ext3_new_inode: Journal has aborted ext3_abort called. EXT3-fs error (device sdb1): ext3_remount: Abort forced by user ext3_abort called. EXT3-fs error (device sdb1): ext3_remount: Abort forced by user 

There was no error message of course because of read-only partition. That’s why we have no chance to detect why MySQL did not start, until we examine OS level issues. In contrast Oracle handles this condition:

[root@bsnew home]# su - oracle -bash-3.2$ sqlplus / as sysdba 
SQL*Plus: Release 11.2.0.4.0 Production on Mon Apr 7 11:35:10 2014 Copyright (c) 1982, 2013, Oracle. All rights reserved. ERROR: ORA-09925: Unable to create audit trail file Linux-x86_64 Error: 30: Read-only file system Additional information: 9925 ORA-09925: Unable to create audit trail file Linux-x86_64 Error: 30: Read-only file system Additional information: 9925 

Of course if you change error log file path to working path there will be messages:

    2015-04-28 08:04:16 7f27a6c847e0 InnoDB: Operating system error number 30 in a file operation. InnoDB: Error number 30 means 'Read-only file system'. InnoDB: Some operating system error numbers are described at InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html 
    2015-04-28 08:04:16 1486 [ERROR] InnoDB: File ./ibdata1: 'create' returned OS error 130. Cannot continue operation 150428 08:04:17 mysqld_safe mysqld from pid file /home/error_log_dir/mysqld-new.pid ended 

But it is not useful at this moment, instead, there should be some message while trying starting MySQL directly to STDOUT.

If you have more test paths check related feature request and add them: #72259

Using GDB, investigating segmentation fault in MySQL

In previous article, we have covered some errors and issues with using MySQL in “disk full” environment. Where there was no space left on device.(See here: Testing Disk Full Conditions)

Today’s scenario is -> Starting MySQL with GTID/binary log enabled, in 0 space left Linux(CentOS 6.5) environment.

If you hit a bug or problem, general rule for helping community to fix it is to provide as much information as possible. Especially useful is to give gdb output from coredump. To get coredump you can read this wonderful article Hunting-The-Core

Now let’s explore our situation. Because our segfault is detected while starting MySQL, it is not possible to attach PID to GDB and also using strace. Our my.cnf file:

[mysqld] 
log_bin = /opt/mysql/datadir/mysql-bin 
log_bin_index = /opt/mysql/datadir/mysql-bin 
sync_binlog = 1 
binlog_format = row 
gtid-mode = on 
log_slave_updates = 1 
enforce-gtid-consistency = true
sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES core-file 
[mysqld_safe]
core_file_size=unlimited 

Starting MySQL:

[root@localhost ~]# /opt/mysql/bin/mysqld_safe --defaults-file=/opt/mysql/my.cnf --user=mysql --datadir=/opt/mysql/datadir --socket=/opt/mysql/datadir/mysqld-new.sock --pid-file=/home/error_log_dir/mysqld-new.pid --port=3307 --log-error=/home/error_log_dir/error.err & 
[1] 2849 
[root@localhost ~]# 150427 06:31:42 mysqld_safe Logging to '/home/error_log_dir/error.err'. 150427 06:31:42 mysqld_safe Starting mysqld daemon with databases from /opt/mysql/datadir /opt/mysql/bin/mysqld_safe: line 166: 3110 Segmentation fault (core dumped) nohup /opt/mysql/bin/mysqld
--defaults-file=/opt/mysql/my.cnf 
--basedir=/opt/mysql    
--datadir=/opt/mysql/datadir 
--plugin-dir=/opt/mysql/lib/plugin --user=mysql     
--log-error=/home/error_log_dir/error.err 
--pid-file=/home/error_log_dir/mysqld-new.pid 
--socket=/opt/mysql/datadir/mysqld-new.sock 
--port=3307 < /dev/null >> /home/error_log_dir/error.err 2>&1 
150427 06:32:07 mysqld_safe mysqld from pid file /home/error_log_dir/mysqld-new.pid ended 

3110 Segmentation fault (core dumped) -> We have core dump. Using gdb with coredump:

[root@localhost coredumps]# gdb /opt/mysql/bin/mysqld core.3110 
BFD: Warning: /home/coredumps/core.3110 is truncated: expected core file size >= 803807232, found: 697573376. 
[New Thread 3110] 
[New Thread 3111] 
Cannot access memory at address 0x7f5ec00ff168 
Cannot access memory at address 0x7f5ec00ff168 
Cannot access memory at address 0x7f5ec00ff168 
Reading symbols from /lib64/ld-linux-x86-64.so.2...
Reading symbols from /usr/lib/debug/lib64/ld-2.12.so.debug...done. done. 
Loaded symbols for /lib64/ld-linux-x86-64.so.2 Failed to read a valid object file image from memory. 
Core was generated by `/opt/mysql/bin/mysqld --defaults-file=/opt/mysql/my.cnf --basedir=/opt/mysql --'. Program terminated with signal 11, Segmentation fault. #0 0x00007f5ebfccd8ac in ?? () 

(gdb) bt #0 0x00007f5ebfccd8ac in ?? () Cannot access memory at address 0x7fffb0aa89b8 

(gdb) bt full #0 0x00007f5ebfccd8ac in ?? () No symbol table info available. Cannot access memory at address 0x7fffb0aa89b8 

Such information is not sufficient further analysis, that’s why you should try to run MySQL start command with-in GDB as follows:

[root@localhost error_log_dir]# gdb /opt/mysql/bin/mysqld 
(gdb) run --defaults-file=/home/error_log_dir/my.cnf --basedir=/opt/mysql --datadir=/opt/mysql/datadir --plugin-dir=/opt/mysql/lib/plugin --user=mysql --log-error=/home/error_log_dir/error.err --pid-file=/home/error_log_dir/mysqld-new.pid --socket=/opt/mysql/datadir/mysqld-new.sock --port=3307 . . 
Program received signal SIGSEGV, Segmentation fault. 0x0000000000000000 in ?? () . . 

(gdb) bt 
    #0 0x0000000000000000 in ?? () 
    #1 0x0000000000ae6242 in my_printf_warning (format=0x1026f08 "Disk is full writing '%s' (Errcode: %d - %s). Waiting for someone to free space...") at /root/mysql-5.6.24/mysys/my_error.c:260 #2 0x0000000000ac9052 in wait_for_free_space (filename=0x1fe7ee0 "/opt/mysql/datadir/mysql-bin.~rec~", errors=0) at /root/mysql-5.6.24/mysys/errors.c:115 
#3 0x0000000000af1ac7 in my_write (Filedes=19, Buffer=0x1964d00 "/opt/mysql/datadir/mysql-bin.000003n", Count=36, MyFlags=52) at /root/mysql-5.6.24/mysys/my_write.c:89 
#4 0x0000000000acd5ae in inline_mysql_file_write (src_file=0x1027708 "/root/mysql-5.6.24/mysys/mf_iocache.c", src_line=1788, file=19, buffer=0x1964d00 "/opt/mysql/datadir/mysql-bin.000003n", count=36, flags=52) at /root/mysql-5.6.24/include/mysql/psi/mysql_file.h:1141 
#5 0x0000000000ad078c in my_b_flush_io_cache (info=0x183c1a8, need_append_buffer_lock=0) at /root/mysql-5.6.24/mysys/mf_iocache.c:1787 
#6 0x0000000000a7132b in MYSQL_BIN_LOG::sync_purge_index_file (this=0x183b400) at /root/mysql-5.6.24/sql/binlog.cc:4420 
#7 0x0000000000a6e206 in MYSQL_BIN_LOG::open_binlog (this=0x183b400, log_name=0x190d130 "/opt/mysql/datadir/mysql-bin", new_name=0x0, io_cache_type_arg=WRITE_CACHE, max_size_arg=1073741824, null_created_arg=false, need_lock_index=true, need_sid_lock=true, extra_description_event=0x0) at /root/mysql-5.6.24/sql/binlog.cc:3146 
#8 0x000000000063ad8e in init_server_components () at /root/mysql-5.6.24/sql/mysqld.cc:5012 
#9 0x000000000063b6e7 in mysqld_main (argc=19, argv=0x186de68) at /root/mysql-5.6.24/sql/mysqld.cc:5455 
#10 0x000000000062fc74 in main (argc=10, argv=0x7fffffffe3d8) at /root/mysql-5.6.24/sql/main.cc:25 ###################### 

(gdb) bt full 
#0 0x0000000000000000 in ?? () No symbol table info available. 
#1 0x0000000000ae6242 in my_printf_warning (format=0x1026f08 "Disk is full writing '%s' (Errcode: %d - %s). Waiting for someone to free space...") at /root/mysql-5.6.24/mysys/my_error.c:260 args = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x7fffffffd8a0, reg_save_area = 0x7fffffffd7e0}} wbuff = "Disk is full writing '/opt/mysql/datadir/mysql-bin.~rec~' (Errcode: 28 - No space left on device). Waiting for someone to free space...0033032737737737717700002103413773673771770000340267376367377177000027133224u00000000Zn33636737717700000000000000000000/35!3663771770000C00000000000000f223!36637717700000100000000000000P31!3663771770000LC_"... _db_stack_frame_ = {func = 0x102c53c "my_write", file = 0x102c518 "/root/mysql-5.6.24/mysys/my_write.c", level = 2147483654, prev = 0x7fffffffd9f0} 
#2 0x0000000000ac9052 in wait_for_free_space (filename=0x1fe7ee0 "/opt/mysql/datadir/mysql-bin.~rec~", errors=0) at /root/mysql-5.6.24/mysys/errors.c:115 errbuf = "No space left on device003252425700350000002303240201000000002723240201000000000033137737734000000 ܆01000000003400000006000000 ܆0100000000@3313773773771770000[3462570000000000 ܆010000000000܆0123000000<305020100000000303050201000000" 
#3 0x0000000000af1ac7 in my_write (Filedes=19, Buffer=0x1964d00 "/opt/mysql/datadir/mysql-bin.000003n", Count=36, MyFlags=52) at /root/mysql-5.6.24/mysys/my_write.c:89 writtenbytes = 18446744073709551615 sum_written = 0 errors = 0 initial_count = 36 _db_stack_frame_ = {func = 0x1027c7b "my_b_flush_io_cache", file = 0x1027708 "/root/mysql-5.6.24/mysys/mf_iocache.c", level = 2147483653, prev = 0x7fffffffdb10}  

From know developers should be able to see exact code line, for further examination. For further reading(to see “bt full” full output) refer related BUG report: #76852 It is already verified.