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

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