MySQL Bugs: #77546: Lost Connection on DDL Query in a large table (optimize table)

Bug #77546	Lost Connection on DDL Query in a large table (optimize table)
Submitted:	29 Jun 2015 14:38	Modified:	15 Nov 2015 21:16
Reporter:	Fabrício Raphael	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: DDL	Severity:	S2 (Serious)
Version:	5.6.25 MySQL Community Server (GPL)	OS:	Ubuntu (14.04 64bit)
Assigned to:		CPU Architecture:	Any
Tags:	add index, DDL, error, Lost connection, Optimize

Description:
I received this error after about 64min that I ran the DDL query 'optimize table post_cache':
"ERROR 2013 (HY000): Lost connection to MySQL server during query"

The same occurred whean I ran another DDL query 'Alter TABLE ... ADD INDEX ...'.

I also try tu run with this configs, and still it did not work:
mysql> SET SESSION autocommit=0, wait_timeout=31536000, SESSION interactive_timeout=31536000, GLOBAL connect_timeout=31536000, net_read_timeout=31536000, net_write_timeout=31536000;

The table contains 90.710.191 rows.

How to repeat:
Follows other relevant information.

CREATE TABLE IF NOT EXISTS `post_cache` (
	`id_post_cache` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
	`post_source` varchar(10) NOT NULL,
	`id_post` bigint(20) unsigned NOT NULL,	
	`date_insert` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
	`date_update` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
	`json` tinyint(1) NOT NULL DEFAULT 0,
	`config_id` bigint(20) NULL DEFAULT NULL,
	`raw_post` text CHARACTER SET utf8 COLLATE utf8_unicode_ci NOT NULL,
	PRIMARY KEY (`id_post_cache`),
	UNIQUE KEY `post_UNIQUE` (`post_source` ASC, `id_post` ASC),
	KEY `json_KEY` (`json` ASC);
	KEY `config_KEY` (`config_id` ASC);
) ENGINE=InnoDB DEFAULT CHARSET=utf8 AUTO_INCREMENT=1;

mysql> select count(*) from post_cache;
+----------+
| count(*) |
+----------+
| 90710191 |
+----------+
1 row in set (32,22 sec)

mysql> show columns from post_cache;
+---------------+---------------------+------+-----+-------------------+-----------------------------+
| Field         | Type                | Null | Key | Default           | Extra                       |
+---------------+---------------------+------+-----+-------------------+-----------------------------+
| id_post_cache | bigint(20) unsigned | NO   | PRI | NULL              | auto_increment              |
| post_source   | varchar(10)         | NO   | MUL | NULL              |                             |
| id_post       | bigint(20) unsigned | NO   |     | NULL              |                             |
| date_insert   | timestamp           | NO   |     | CURRENT_TIMESTAMP |                             |
| date_update   | timestamp           | NO   |     | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP |
| json          | tinyint(1)          | NO   | MUL | 0                 |                             |
| config_id     | bigint(20)          | YES  | MUL | NULL              |                             |
| raw_post      | text                | NO   |     | NULL              |                             |
+---------------+---------------------+------+-----+-------------------+-----------------------------+
8 rows in set (0,04 sec)

mysql> show keys from post_cache;
+------------+------------+-------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table      | Non_unique | Key_name    | Seq_in_index | Column_name   | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+------------+------------+-------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| post_cache |          0 | PRIMARY     |            1 | id_post_cache | A         |    45059494 |     NULL | NULL   |      | BTREE      |         |               |
| post_cache |          0 | post_UNIQUE |            1 | post_source   | A         |           2 |     NULL | NULL   |      | BTREE      |         |               |
| post_cache |          0 | post_UNIQUE |            2 | id_post       | A         |    45059494 |     NULL | NULL   |      | BTREE      |         |               |
| post_cache |          1 | json_KEY    |            1 | json          | A         |           2 |     NULL | NULL   |      | BTREE      |         |               |
| post_cache |          1 | config_KEY  |            1 | config_id     | A         |        1448 |     NULL | NULL   | YES  | BTREE      |         |               |
+------------+------------+-------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
5 rows in set (0,00 sec)

mysql> show variables like '%timeout%'; 
+-----------------------------+----------+
| Variable_name               | Value    |
+-----------------------------+----------+
| connect_timeout             | 10       |
| delayed_insert_timeout      | 300      |
| innodb_flush_log_at_timeout | 1        |
| innodb_lock_wait_timeout    | 50       |
| innodb_rollback_on_timeout  | OFF      |
| interactive_timeout         | 28800    |
| lock_wait_timeout           | 31536000 |
| net_read_timeout            | 30       |
| net_write_timeout           | 60       |
| rpl_stop_slave_timeout      | 31536000 |
| slave_net_timeout           | 3600     |
| wait_timeout                | 28800    |
+-----------------------------+----------+
12 rows in set (0,14 sec)

And the error ocorred when I ran each of the commands below:

mysql> optimize table post_cache;
ERROR 2013 (HY000): Lost connection to MySQL server during query

mysql> ALTER TABLE `post_cache` ADD INDEX `date_post_cache_KEY` (`date_insert` ASC);
ERROR 2013 (HY000): Lost connection to MySQL server during query

Follow the log error:

2015-06-29 10:55:51 28504 [ERROR] InnoDB: Tried to read 16384 bytes at offset 361493168128. Was only able to read 4096.
2015-06-29 10:55:51 28504 [ERROR] InnoDB: File (unknown): 'read' returned OS error 0. Cannot continue operation
150629 10:55:52 mysqld_safe Number of processes running now: 0
150629 10:55:52 mysqld_safe mysqld restarted
2015-06-29 10:55:52 0 [Note] /usr/sbin/mysqld (mysqld 5.6.25) starting as process 1253 ...
2015-06-29 10:55:52 1253 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2015-06-29 10:55:52 1253 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)

2015-06-29 10:55:52 1253 [Note] Plugin 'FEDERATED' is disabled.
2015-06-29 10:55:52 1253 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-06-29 10:55:52 1253 [Note] InnoDB: The InnoDB memory heap is disabled
2015-06-29 10:55:52 1253 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-06-29 10:55:52 1253 [Note] InnoDB: Memory barrier is not used
2015-06-29 10:55:52 1253 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-06-29 10:55:52 1253 [Note] InnoDB: Using Linux native AIO
2015-06-29 10:55:52 1253 [Note] InnoDB: Using CPU crc32 instructions
2015-06-29 10:55:52 1253 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2015-06-29 10:55:52 1253 [Note] InnoDB: Completed initialization of buffer pool
2015-06-29 10:55:52 1253 [Note] InnoDB: Highest supported file format is Barracuda.
2015-06-29 10:55:52 1253 [Note] InnoDB: The log sequence numbers 765842363764 and 765842363764 in ibdata files do not match the log sequence number 765842870764 in the ib_logfiles!
2015-06-29 10:55:52 1253 [Note] InnoDB: Database was not shutdown normally!
2015-06-29 10:55:52 1253 [Note] InnoDB: Starting crash recovery.
2015-06-29 10:55:52 1253 [Note] InnoDB: Reading tablespace information from the .ibd files...
2015-06-29 10:55:52 1253 [Note] InnoDB: Restoring possible half-written data pages 
2015-06-29 10:55:52 1253 [Note] InnoDB: from the doublewrite buffer...
2015-06-29 10:55:52 1253 [Note] InnoDB: 128 rollback segment(s) are active.
2015-06-29 10:55:52 1253 [Note] InnoDB: Waiting for purge to start
2015-06-29 10:55:52 1253 [Note] InnoDB: 5.6.25 started; log sequence number 765842870764
2015-06-29 10:55:52 1253 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2015-06-29 10:55:52 1253 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2015-06-29 10:55:52 1253 [Note] Server socket created on IP: '0.0.0.0'.
2015-06-29 10:55:52 1253 [Note] Event Scheduler: Loaded 0 events
2015-06-29 10:55:52 1253 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.25'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server (GPL)

The error still persist ...

mysql> SET SESSION wait_timeout=31536000, interactive_timeout=31536000, net_read_timeout=31536000, net_write_timeout=31536000, innodb_lock_wait_timeout=31536000;
Query OK, 0 rows affected (0,00 sec)

mysql> SET GLOBAL connect_timeout=31536000, slave_net_timeout=31536000;
Query OK, 0 rows affected (0,00 sec)

mysql> show variables like '%timeout%';
+-----------------------------+----------+
| Variable_name               | Value    |
+-----------------------------+----------+
| connect_timeout             | 31536000 |
| delayed_insert_timeout      | 300      |
| innodb_flush_log_at_timeout | 1        |
| innodb_lock_wait_timeout    | 31536000 |
| innodb_rollback_on_timeout  | OFF      |
| interactive_timeout         | 31536000 |
| lock_wait_timeout           | 31536000 |
| net_read_timeout            | 31536000 |
| net_write_timeout           | 31536000 |
| rpl_stop_slave_timeout      | 31536000 |
| slave_net_timeout           | 31536000 |
| wait_timeout                | 31536000 |
+-----------------------------+----------+
12 rows in set (0,00 sec)

mysql> optimize table post_cache;
ERROR 2013 (HY000): Lost connection to MySQL server during query

I encounter the similar symptom (connection lost) during DDL. The cause of connection lost is that the mysqld gone away from the OS without any error log. 
As of 5.6.24 on Windows, it only left a 0xC0000005 error code without any more information. (By the way, the symptom also happens with 5.7.8 when using transparent table compression with 512 byte NTFS cluster on Windows.)

Besides, after restart mysqld, it does not clean up the #XXX.frm and #XXX.ibd. They cannot be dropped by the drop table command. However, if we delete the files manually and start mysqld, it cannot be started and complains about the inconsistency about the data dictionary problem in ibdata1. In such case, we have to start mysqld with innodb_force_recovery=1 to let MySQL "forget" about the #XXX.frm and #XXX.ibd tables. Then, start the MySQL as usual to return to the state before the DDL command which crashes mysqld.

Please try version 5.6.27 and reopen this bug with your results. Thanks.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Got the error on 5.7.17 installed from official docker image.