Bug #75783 Delete a big data table throws innodb crash
Submitted: 5 Feb 2015 3:42 Modified: 5 Mar 2015 15:15
Reporter: workwyz wang Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.6.16 OS:Linux (Centos6.3)
Assigned to: CPU Architecture:Any

[5 Feb 2015 3:42] workwyz wang 
Description:
2015-02-05 04:00:33 28537 [ERROR] InnoDB: Tried to read 16384 bytes at offset 321470464. Was only able to read -1.
2015-02-05 04:00:33 7fc3af9a6700  InnoDB: Operating system error number 5 in a file operation.
InnoDB: Error number 5 means 'Input/output error'.
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-02-05 04:00:33 28537 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation
150205 04:00:33 mysqld_safe Number of processes running now: 0
150205 04:00:33 mysqld_safe mysqld restarted
2015-02-05 04:00:33 32650 [Note] Plugin 'FEDERATED' is disabled.
2015-02-05 04:00:33 32650 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-02-05 04:00:33 32650 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-05 04:00:33 32650 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-02-05 04:00:33 32650 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-05 04:00:33 32650 [Note] InnoDB: Using CPU crc32 instructions
2015-02-05 04:00:33 32650 [Note] InnoDB: Initializing buffer pool, size = 8.0G
2015-02-05 04:00:34 32650 [Note] InnoDB: Completed initialization of buffer pool
2015-02-05 04:00:34 32650 [Note] InnoDB: Highest supported file format is Barracuda.
2015-02-05 04:00:34 32650 [Note] InnoDB: Log scan progressed past the checkpoint lsn 147995015039
2015-02-05 04:00:34 32650 [Note] InnoDB: Database was not shutdown normally!
2015-02-05 04:00:34 32650 [Note] InnoDB: Starting crash recovery.
2015-02-05 04:00:34 32650 [Note] InnoDB: Reading tablespace information from the .ibd files...
2015-02-05 04:00:34 32650 [Note] InnoDB: Restoring possible half-written data pages 
2015-02-05 04:00:34 32650 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 148000257536
InnoDB: Doing recovery: scanned up to log sequence number 148005500416
InnoDB: Doing recovery: scanned up to log sequence number 148010743296
InnoDB: Doing recovery: scanned up to log sequence number 148015986176
InnoDB: Doing recovery: scanned up to log sequence number 148021229056
InnoDB: Doing recovery: scanned up to log sequence number 148026471936
InnoDB: Doing recovery: scanned up to log sequence number 148031714816
InnoDB: Doing recovery: scanned up to log sequence number 148036957696
InnoDB: Doing recovery: scanned up to log sequence number 148042200576
InnoDB: Doing recovery: scanned up to log sequence number 148047443456
InnoDB: Doing recovery: scanned up to log sequence number 148052686336
InnoDB: Doing recovery: scanned up to log sequence number 148057929216
InnoDB: Doing recovery: scanned up to log sequence number 148059174750
InnoDB: Transaction 1824957737 was in the XA prepared state.
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 152261 row operations to undo
InnoDB: Trx id counter is 1824958208
2015-02-05 04:00:39 32650 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 714968388, file name mysql-bin.000115
2015-02-05 04:01:51 32650 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2015-02-05 04:01:51 7f8029c1f700  InnoDB: Rolling back trx with id 1824955414, 152261 rows to undo

InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002015-02-05 04:01:57 32650 [Note] InnoDB: Rollback of trx with id 1824955414 completed
2015-02-05 04:01:57 7f8029c1f700  InnoDB: Rollback of non-prepared transactions completed
2015-02-05 04:03:06 32650 [Note] InnoDB: Waiting for purge to start
2015-02-05 04:03:06 32650 [Note] InnoDB: 5.6.16 started; log sequence number 148059174750
2015-02-05 04:03:06 32650 [Note] Recovering after a crash using /data/mysql/data/mysql-bin
2015-02-05 04:03:18 32650 [Note] Starting crash recovery...
2015-02-05 04:03:18 7f828e8c27e0  InnoDB: Starting recovery for XA transactions...
2015-02-05 04:03:18 7f828e8c27e0  InnoDB: Transaction 1824957737 in prepared state after recovery
2015-02-05 04:03:18 7f828e8c27e0  InnoDB: Transaction contains changes to 1 rows
2015-02-05 04:03:18 7f828e8c27e0  InnoDB: 1 transactions in prepared state after recovery
2015-02-05 04:03:18 32650 [Note] Found 1 prepared transaction(s) in InnoDB
2015-02-05 04:03:18 32650 [Note] Crash recovery finished.
2015-02-05 04:03:19 32650 [Note] RSA private key file not found: /data/mysql/data//private_key.pem. Some authentication plugins will not work.
2015-02-05 04:03:19 32650 [Note] RSA public key file not found: /data/mysql/data//public_key.pem. Some authentication plugins will not work.
2015-02-05 04:03:19 32650 [Note] Server hostname (bind-address): '*'; port: 3306
2015-02-05 04:03:19 32650 [Note] IPv6 is available.
2015-02-05 04:03:19 32650 [Note]   - '::' resolves to '::';
2015-02-05 04:03:19 32650 [Note] Server socket created on IP: '::'.
2015-02-05 04:03:19 32650 [Note] Event Scheduler: Loaded 0 events
2015-02-05 04:03:19 32650 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.16-log'  socket: '/data/mysql/data/mysql.sock'  port: 3306  Source distribution

How to repeat:
1,CHECK TABLE tbl_users;
2,start crash rebuild.

2015-02-05 11:08:08 32650 [ERROR] InnoDB: Tried to read 16384 bytes at offset 321470464. Was only able to read -1.
2015-02-05 11:08:08 7f802530c700  InnoDB: Operating system error number 5 in a file operation.
InnoDB: Error number 5 means 'Input/output error'.
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-02-05 11:08:08 32650 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation
150205 11:08:09 mysqld_safe Number of processes running now: 0
150205 11:08:09 mysqld_safe mysqld restarted
2015-02-05 11:08:09 1940 [Note] Plugin 'FEDERATED' is disabled.
2015-02-05 11:08:09 1940 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-02-05 11:08:09 1940 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-05 11:08:09 1940 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-02-05 11:08:09 1940 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-05 11:08:09 1940 [Note] InnoDB: Using CPU crc32 instructions
2015-02-05 11:08:09 1940 [Note] InnoDB: Initializing buffer pool, size = 8.0G
2015-02-05 11:08:09 1940 [Note] InnoDB: Completed initialization of buffer pool
2015-02-05 11:08:09 1940 [Note] InnoDB: Highest supported file format is Barracuda.
2015-02-05 11:08:09 1940 [Note] InnoDB: Log scan progressed past the checkpoint lsn 148209004486
2015-02-05 11:08:09 1940 [Note] InnoDB: Database was not shutdown normally!
2015-02-05 11:08:09 1940 [Note] InnoDB: Starting crash recovery.
2015-02-05 11:08:09 1940 [Note] InnoDB: Reading tablespace information from the .ibd files...
2015-02-05 11:08:10 1940 [Note] InnoDB: Restoring possible half-written data pages 
2015-02-05 11:08:10 1940 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 148214246912
InnoDB: Doing recovery: scanned up to log sequence number 148219489792
InnoDB: Doing recovery: scanned up to log sequence number 148224732672
InnoDB: Doing recovery: scanned up to log sequence number 148229975552
InnoDB: Doing recovery: scanned up to log sequence number 148235218432
InnoDB: Doing recovery: scanned up to log sequence number 148240461312
InnoDB: Doing recovery: scanned up to log sequence number 148245704192
InnoDB: Doing recovery: scanned up to log sequence number 148250947072
InnoDB: Doing recovery: scanned up to log sequence number 148256189952
InnoDB: Doing recovery: scanned up to log sequence number 148256849781
InnoDB: Transaction 1827846298 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 1827846656
2015-02-05 11:08:13 1940 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 98666293, file name mysql-bin.000116
2015-02-05 11:08:38 1940 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2015-02-05 11:08:38 7fab276b8700  InnoDB: Rollback of non-prepared transactions completed
2015-02-05 11:09:01 1940 [Note] InnoDB: Waiting for purge to start
2015-02-05 11:09:01 1940 [Note] InnoDB: 5.6.16 started; log sequence number 148256849781
2015-02-05 11:09:01 1940 [Note] Recovering after a crash using /data/mysql/data/mysql-bin
2015-02-05 11:09:02 1940 [Note] Starting crash recovery...
2015-02-05 11:09:02 7fad8c5117e0  InnoDB: Starting recovery for XA transactions...
2015-02-05 11:09:02 7fad8c5117e0  InnoDB: Transaction 1827846298 in prepared state after recovery
2015-02-05 11:09:02 7fad8c5117e0  InnoDB: Transaction contains changes to 1 rows
2015-02-05 11:09:02 7fad8c5117e0  InnoDB: 1 transactions in prepared state after recovery
2015-02-05 11:09:02 1940 [Note] Found 1 prepared transaction(s) in InnoDB
2015-02-05 11:09:02 1940 [Note] Crash recovery finished.
2015-02-05 11:09:02 1940 [Note] RSA private key file not found: /data/mysql/data//private_key.pem. Some authentication plugins will not work.
2015-02-05 11:09:02 1940 [Note] RSA public key file not found: /data/mysql/data//public_key.pem. Some authentication plugins will not work.
2015-02-05 11:09:02 1940 [Note] Server hostname (bind-address): '*'; port: 3306
2015-02-05 11:09:02 1940 [Note] IPv6 is available.
2015-02-05 11:09:02 1940 [Note]   - '::' resolves to '::';
2015-02-05 11:09:02 1940 [Note] Server socket created on IP: '::'.
2015-02-05 11:09:02 1940 [Note] Event Scheduler: Loaded 0 events
2015-02-05 11:09:02 1940 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.16-log'  socket: '/data/mysql/data/mysql.sock'  port: 3306  Source distribution
2015-02-05 11:10:06 1940 [ERROR] /usr/local/mysql/bin/mysqld: Sort aborted: Query execution was interrupted
2015-02-05 11:10:08 1940 [ERROR] /usr/local/mysql/bin/mysqld: Sort aborted: Query execution was interrupted
[5 Feb 2015 3:45] workwyz wang 
The tbl_users about have 200W row data.

I See This:
Bug #30201	crash with query cache when killing a select

But Not Sure Yes/No /
[5 Feb 2015 15:15] MySQL Verification Team 
Please test with new version 5.6.23. Thanks.
[6 Mar 2015 1:00] Bugs System 
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".