MySQL LogRotate script

Did you ever try to use log rotate facility in Linux with MySQL? There is no need to script one for this purpose, it is already installed. From MySQL spec file, it looks for logrotate.d folder:

    # Ensure that needed directories exists 
    install -d $RBR%{_sysconfdir}/{logrotate.d,init.d}

As well as there is dedicated mysql-log-rotate.sh script for installing logrotate script. The script path is: /mysql-5.6.24/support-files/mysql-log-rotate.sh Again from spec file:

    # Install logrotate and autostart 
    install -m 644 $MBD/release/support-files/mysql-log-rotate $RBR%{_sysconfdir}/logrotate.d/mysql

After installing there will be mysql script in /etc/logrottate.d/.

   # The log file name and location can be set in
   # /etc/my.cnf by setting the "log-error" option
   # in either [mysqld] or [mysqld_safe] section as
   # follows:
   #
   # [mysqld]
   # log-error=/var/lib/mysql/mysqld.log
   #
   # In case the root user has a password, then you
   # have to create a /root/.my.cnf configuration file
   # with the following content:
   #
   # [mysqladmin]
   # password = <secret> 
   # user= root
   #
   # where "<secret>" is the password. 
   #
   # ATTENTION: The /root/.my.cnf file should be readable
   # _ONLY_ by root !

   /var/lib/mysql/mysqld.log {
         # create 600 mysql mysql
         notifempty
         daily
         rotate 5
          missingok
         compress
    postrotate
         # just if mysqld is really running
         if test -x /usr/bin/mysqladmin && 
          /usr/bin/mysqladmin ping &>/dev/null
       then
          /usr/bin/mysqladmin flush-logs
       fi
   endscript
  }

There is 2 simple and critical problem with this script. First of all the name of error log file. If MySQL started from default my.cnf file, path for error log file will be: /var/log/mysqld.log

     [mysqld_safe] 
     log-error=/var/log/mysqld.log 
     pid-file=/var/run/mysqld/mysqld.pid

But in script it is defined as: /var/lib/mysql/mysqld.log Even if you comment out default settings in my.cnf file, MySQL by default will create error log file as follows: datadir + host_name.err = /var/lib/mysql/host_name.err Again there will be no such error log file defined in log rotate script. Second problem is usage of mysqladmin. Script is calling mysqladmin without any password. We assume that there is no such MySQL instance without user, at least in production environment:

     [root@centos7 ~]# /usr/bin/mysqladmin ping /usr/bin/mysqladmin: connect to server at  'localhost' failed error: 'Access denied for user 'root'@'localhost' (using password: NO)'   

     [root@centos7 ~]# /usr/bin/mysqladmin flush-logs /usr/bin/mysqladmin: connect to server at  'localhost' failed error: 'Access denied for user 'root'@'localhost' (using password: NO)' 

From now we know that, after installing MySQL there will be non-working log rotate script, which will fail due to explanations above. Related report is: #73949

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.

Testing “disk full” conditions in MySQL

How MySQL will act if there is no space left on hard disk? To answer this question, let’s test it: Our first test is with MySQL 5.6.24-debug with disabled binary log: Trying to import huge dump, after while it says table is full:

Query OK, 12725 rows affected (2.46 sec) Records: 12725 Duplicates: 0 Warnings: 0
Query OK, 12724 rows affected (2.40 sec) Records: 12724 Duplicates: 0 Warnings: 0
Query OK, 12726 rows affected (2.53 sec) Records: 12726 Duplicates: 0 Warnings: 0
ERROR 1114 (HY000): The table 'sales' is full 
ERROR 1114 (HY000): The table 'sales' is full ERROR 1114 (HY000): The table 'sales' is full

In error log you will see something like:

[root@localhost mysql]# tail -f /opt/mysql/datadir/error.err 
Version: '5.6.24-debug' socket: '/opt/mysql/datadir/mysqld-new.sock' port: 3307     Shahriyar Rzayev's MySQL 
2015-04-24 03:56:09 7fabeffff700 InnoDB: Error: Write to file ./sales2/sales.ibd failed at offset 34603008. InnoDB: 1048576 bytes should have been written, only 1011712 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 
2015-04-24 03:56:09 21838 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 
2015-04-24 03:56:12 21838 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 
2015-04-24 03:56:15 21838 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 
2015-04-24 03:56:19 21838 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 
2015-04-24 03:56:20 21838 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 

At this point “Operating system error number 11.” and OS disk usage is:

[root@localhost ~]# df -h 
Filesystem Size Used Avail Use% Mounted on 
/dev/mapper/VolGroup-lv_root 6.7G 6.3G 24M 100% / 
tmpfs 246M 0 246M 0% /dev/shm 
/dev/sda1 485M 55M 405M 12% /boot

If we continue our import process with another database.
Error will change:

mysql> create database sales3; 
Query OK, 
1 row affected, 1 warning (0.08 sec) 
mysql> use sales3; 
Database changed 
ERROR 3 (HY000): Error writing file './sales3/Product_Codes.frm' (Errcode: 28 - No space left on device) 
ERROR 1146 (42S02): Table 'sales3.Product_Codes' doesn't exist 
ERROR 1146 (42S02): Table 'sales3.Product_Codes' doesn't exist Query OK, 0 rows affected (0.00 sec) 
ERROR 1146 (42S02): Table 'sales3.Product_Codes' doesn't exist Query OK, 0 rows affected (0.00 sec) 
ERROR 3 (HY000): Error writing file './sales3/account_balance.frm' (Errcode: 28 - No space left on device) 
ERROR 1146 (42S02): Table 'sales3.account_balance' doesn't exist 
ERROR 1146 (42S02): Table 'sales3.account_balance' doesn't exist 
ERROR 1146 (42S02): Table 'sales3.account_balance' doesn't exist  

Disk usage is:

[root@localhost ~]# df -h 
Filesystem Size Used Avail Use% Mounted on 
/dev/mapper/VolGroup-lv_root 6.7G 6.3G 16M 100% / 
tmpfs 246M 0 246M 0% /dev/shm 
/dev/sda1 485M 55M 405M 12% /boot

Of course there will be NO entry in error log because disk is full.
That’s why let’s change error log path to another directory and start from here:

[root@localhost error_log_dir]# setenforce 0 (use only in test environment)
[root@localhost error_log_dir]# chown mysql:mysql /home/error_log_dir/
[root@localhost mysql]# /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=/opt/mysql/datadir/mysqld-new.pid --port=3307 --log-error=/home/error_log_dir/error.err & 
[root@localhost mysql]# 150424 05:03:06 mysqld_safe Logging to '/home/error_log_dir/error.err'. 150424 05:03:06 mysqld_safe Starting mysqld daemon with databases from /opt/mysql/datadir 150424 05:03:13 mysqld_safe Number of processes running now: 0 150424 05:03:13 mysqld_safe mysqld restarted  

It will continuously restart, because of related 28 – No space left on device error:

2015-04-24 05:03:36 22371 [ERROR] /opt/mysql/bin/mysqld: Error writing file '/opt/mysql/datadir/mysqld-new.pid' (Errcode: 28 - No space left on device)
2015-04-24 05:03:36 22371 [ERROR] Can't start server: can't create PID file: No space left on device

If we change PID file path it will start as usual:

[root@localhost mysql]# /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 & 

Another thing we should note that, after getting -> Errcode: 28 – No space left on device , if you try to create new database:

mysql> create database sales3; Query OK, 1 row affected, 1 warning (0.12 sec)
mysql> show warnings;  
| Error | 3 | Error writing file './sales3/db.opt' (Errcode: 28 - No space left on device) | 

db.opt file will be created as empty file. If you want to create new table:

mysql> create table t1(id int); 
ERROR 3 (HY000): Error writing file './sales3/t1.frm' (Errcode: 28 - No space left on device)

And now let’s enable binary log and then try to import dump. Related to Binary Log error’s due full disk there was a BUG fixed from 5.6.23 version of MySQL: #73365 And another one still waiting as OPEN:#72437 Where i got an error: [ERROR] Error in Log_event::read_log_event(): ‘read error’, data_len: 2070, event_type: 29 And interesting warning: [Warning] Error reading GTIDs from binary log: -1

For activating binary log and GTID add followings to my.cnf file:

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  

Then drop all previous imports(databases) and again try to import dump. You will get a new problem which i have reported, while writing this article: #76825 To reproduce this report, read “How to repeat” section. Another interesting thing, i want to note is, after detecting full disk error, if we try to create view, we will hit another reported issue: #76827 (I have disabled GTID/binary log while testing views)

UPDATE 1

If you try to create a procedure while disk is full, you will get a table corruption of mysql.proc table. From error log:

2015-04-27 05:30:22 1485 [Warning] Disk is full writing './mysql/proc.MYD' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2015-04-27 05:30:22 1485 [Warning] Retry in 60 secs. Message reprinted in 600 secs 
2015-04-27 05:39:23 1485 [ERROR] /opt/mysql/bin/mysqld: Incorrect key file for table './mysql/proc.MYI'; try to repair it 
2015-04-27 05:39:23 1485 [ERROR] Got an error from thread_id=1, /root/mysql-5.6.24/storage/myisam/mi_write.c:223 
2015-04-27 05:39:23 1485 [ERROR] MySQL thread id 1, OS thread handle 0x7fe47ed20700, query id 756 localhost root System lock  

If you select from this table:

mysql> select * from mysql.proc; 
ERROR 1194 (HY000): Table 'proc' is marked as crashed and should be repaired 

Same thing if you create a function. And even with events:

2015-04-27 05:56:34 1485 [ERROR] /opt/mysql/bin/mysqld: Incorrect key file for table './mysql/event.MYI'; try to repair it 
2015-04-27 05:56:34 1485 [ERROR] Got an error from thread_id=7, /root/mysql-5.6.24/storage/myisam/mi_write.c:223 
2015-04-27 05:56:34 1485 [ERROR] MySQL thread id 7, OS thread handle 0x7fe47ed20700, query id 789 localhost root System lock

UPDATE 2

When disk full condition occurs you will not be able to create and drop indexes even from empty tables:

mysql> select count(*) from customers;
+----------+ 
| count(*) | 
+----------+ 
| 0 | 
+----------+ 
1 row in set (0.04 sec) 

mysql> alter table customers add index(COMMENT_ID); 
ERROR 3 (HY000): Error writing file './proc_func/#sql-5cd_a.frm' (Errcode: 28 - No space left on device) mysql> alter table customers drop index `customer_name_i`; 
ERROR 3 (HY000): Error writing file './proc_func/#sql-5cd_a.frm' (Errcode: 28 - No space left on device) 

UPDATE 3

It is impossible drop database after crashing ./mysql/proc table:

mysql> drop database proc_func; 
ERROR 145 (HY000): Table './mysql/proc' is marked as crashed and should be repaired mysql> drop database sales; 
ERROR 145 (HY000): Table './mysql/proc' is marked as crashed and should be repaired mysql> drop database sales2; 
ERROR 145 (HY000): Table './mysql/proc' is marked as crashed and should be repaired 

After repairing proc table if you try to drop database, there will be warnings about mysql.event table:

mysql> drop database test_disk; 
Query OK, 0 rows affected, 2 warnings (0.10 sec) 
mysql> show warnings; +-------+------+-------------------------------------------------------------------+ | Level | Code | Message | +-------+------+-------------------------------------------------------------------+ | Error | 145 | Table './mysql/event' is marked as crashed and should be repaired | 
| Error | 1194 | Table 'event' is marked as crashed and should be repaired | +-------+------+-------------------------------------------------------------------+ 
2 rows in set (0.02 sec)  

At this moment, that’s all. Will update this article every time, when i find related issues. Thank you for reading.

Playing with count(*) optimizer work

Article about bug report #68814 related to testing count(*) explain plan.
Our sales table huge enough to play with.

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

First with regular count(*) without where clause:

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) 

Estimated rows -> rows: 2489938 Then with {where 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)

Estimated rows -> rows: 1244969 -> so there is difference between query with {sales_id > 0} and with no clause.

Another one with {where sales_id > 1800000}:

mysql> explain select count(*) from sales where sales_id > 1800000G
*************************** 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) 

Estimated rows -> rows: 1244969 So there is no difference between {sales_id > 1800000} and {sales_id > 0} (by mean of explain plan and estimated rows)

Another interesting thing:

-- 1 
mysql> explain select count(*) from sales where sales_id >0 or 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: 1244970 
Extra: Using where; Using index 
1 row in set (0.00 sec)

Estimated rows -> rows: 1244969 + 1

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

Estimated rows: 2489938

mysqldiskusage – source code examination

As you know there is a great toolset named “MySQL Utilities”, which you can use for solving various administrative tasks. mysqldiskusage utility is for calculating MySQL Server’s disk usage and generating informative reports. Of course this project is open source and everybody could review the source code. A few words about how mysqldiskusage calculates database disk usage will be crucial for understanding algorithm. The source tree is: mysql-utilities-1.5.4/scripts/mysqldiskusage.py If you open this Python file you will see (line 169-175) :

# We do database disk usage by default. 
try: 
    diskusage.show_database_usage(servers[0], datadir, args, options) 
except UtilError: _, e, _ = sys.exc_info() 
    print("ERROR: %s" % e.errmsg) 
    sys.exit(1) 

By default it shows database disk usage and calling another function named show_database_usage from mysql-utilities-1.5.4/mysql/utilities/command/diskusage.py file. Now if we open up this diskusage.py file and search for show_database_usage function, you should see that in turn this function uses another function named _build_db_list. From _build_db_list it gets back all necessary information as in code stated clearly(line 550-562):

# Get list of databases with sizes and formatted when necessary columns, rows     
db_total = _build_db_list(server, res, dblist, datadir, fmt == "grid", have_read, verbosity, include_empty or do_all, is_remote) 
if not quiet: 
    print "# Database totals:" print_list(sys.stdout, fmt, columns, rows, no_headers) 
if not quiet: _print_size("nTotal database disk usage = ", db_total) 
    print 

Now we know that all calculations are happened in _build_db_list function. If you search and find this function(begins from line 360) you can see that, in fact mysqldiskusage is calculating database disk usage as follows:

It finds (data_length + index_length) from information_schema.tables per database manner

Then it sum ups (data_length + index_length) with misc_files variable data which is in fact returned by _get_db_dir_size function. But what is this misc_files? Logically misc_files must be .opt and .frm files. So misc_files must not be an “.MYD” , “.MYI”, “.IBD”, “general_log”, “slow_log”.

So in fact mysqldiskusage calculates database disk usage as -> (data_length + index_length)[size in bytes] + (.opt+.frm)[size in bytes]. First of all we must insist on not using information_schema for accurate disk usage calculation because of simple rule: “InnoDB preallocates pages(16Kib) for further table usage, but data_length column will not show these pages”

As proof of concept let’s create sample empty table:

mysql> create database test; 
Query OK, 
1 row affected (0,01 sec) 
mysql> use test; 
Database changed 
mysql> 
select data_length, index_length from information_schema.tables where table_schema='test' and table_name='t1'; 
+-------------+--------------+ 
| data_length | index_length | 
+-------------+--------------+ 
| 16384 | 0 | 
+-------------+--------------+ 
1 row in set (0,00 sec) 

If we consider that our exact table size is 16384 bytes, we are in wrong direction. In fact if we use OS commands we could see that the exact size of table is 98304 bytes:

[root@node1 ~]# ls -lt /var/lib/mysql/test/ 
total 208 
-rw-rw----. 1 mysql mysql 98304 Apr 18 11:44 t1.ibd 

So when we create an InnoDB table it is preallocates 6 pages(16Kib*6 = 98304) but only 1 page shown up from data_length column. Now let’s come back to our misc_files or exactly _get_db_dir_size() function. From source code we can see that there is no a check for “.IBD” files:

... 
for item in os.listdir(folder): 
    name, ext = os.path.splitext(item) 
    if ext.upper() not in (".MYD", ".MYI") and  name.upper() not in ('SLOW_LOG', 'GENERAL_LOG'): 
        itemfolder = os.path.join(folder, item) 
    ... 

Because of this calculation is wrong for databases as we see from output:

[root@node1 ~]# mysqldiskusage --server=root_pass -vvv 
# Source on localhost: ... connected. 
# Database totals: 
+---------------------+--------------+--------------+--------------+--------------+ | db_name | db_dir_size | data_size | misc_files | total | +---------------------+--------------+--------------+--------------+--------------+ | employees | 242.523.049 | 205.979.648 | 242.523.049 | 448.502.697 | 

As you see it sum ups data_size with misc_files and gets back total as 448.502.697 bytes. But in fact our employees database is exactly 242.523.049 bytes. And of course the: Total database disk usage = 450.940.391 bytes or 430,05 MB is wrong as well. For further exploration and how to patch source code see related BUG REPORT #76703.