MySQL Bugs: #96776: The database crashes and restarts automatically.Then keep this status..

Bug #96776	The database crashes and restarts automatically.Then keep this status..
Submitted:	6 Sep 2019 9:18	Modified:	10 Sep 2019 8:23
Reporter:	Jhonson Leo	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: DML	Severity:	S1 (Critical)
Version:	5.6.32	OS:	CentOS (CentOS release 6.9 (Final))
Assigned to:	MySQL Verification Team	CPU Architecture:	Any

Description:
2019-09-06 08:24:55 15782 [ERROR] InnoDB: Error in system call pread(). The operating system error number is 5.
2019-09-06 08:24:55 7f9d1b514700  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
2019-09-06 08:24:56 15782 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation
pure virtual method called
pure virtual method called
pure virtual method called
pure virtual method called
pure virtual method called
terminate called recursively
pure virtual method called
terminate called recursively
pure virtual method called
pure virtual method called
terminate called recursively
terminate called recursively
pure virtual method called
terminate called recursively
pure virtual method called
terminate called recursively
terminate called without an active exception
terminate called without an active exception
terminate called without an active exception

...

2019-09-06 14:14:39 3448 [ERROR] InnoDB: Error in system call pread(). The operating system error number is 5.
2019-09-06 14:14:39 7f30fc28d700  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
2019-09-06 14:14:39 3448 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation
190906 14:14:40 mysqld_safe Number of processes running now: 0
190906 14:14:40 mysqld_safe mysqld restarted
2019-09-06 14:14:40 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-09-06 14:14:40 0 [Note] /home/mysql/mysql-5.6.32_3306/bin/mysqld (mysqld 5.6.32-log) starting as process 6945 ...
2019-09-06 14:14:40 6945 [Note] Plugin 'FEDERATED' is disabled.
2019-09-06 14:14:40 6945 [Note] InnoDB: Using atomics to ref count buffer pool pages
2019-09-06 14:14:40 6945 [Note] InnoDB: The InnoDB memory heap is disabled
2019-09-06 14:14:40 6945 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-06 14:14:40 6945 [Note] InnoDB: Memory barrier is not used
2019-09-06 14:14:40 6945 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-09-06 14:14:40 6945 [Note] InnoDB: Using Linux native AIO
2019-09-06 14:14:40 6945 [Note] InnoDB: Using CPU crc32 instructions
2019-09-06 14:14:40 6945 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2019-09-06 14:14:40 6945 [Note] InnoDB: Completed initialization of buffer pool
2019-09-06 14:14:40 6945 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-06 14:14:40 6945 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1349222895076
2019-09-06 14:14:40 6945 [Note] InnoDB: Database was not shutdown normally!
2019-09-06 14:14:40 6945 [Note] InnoDB: Starting crash recovery.
2019-09-06 14:14:40 6945 [Note] InnoDB: Reading tablespace information from the .ibd files...
2019-09-06 14:14:40 6945 [Note] InnoDB: Restoring possible half-written data pages 
2019-09-06 14:14:40 6945 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1349228137472
InnoDB: Doing recovery: scanned up to log sequence number 1349233380352
InnoDB: Doing recovery: scanned up to log sequence number 1349238623232
InnoDB: Doing recovery: scanned up to log sequence number 1349243866112
InnoDB: Doing recovery: scanned up to log sequence number 1349249108992
InnoDB: Doing recovery: scanned up to log sequence number 1349254351872
InnoDB: Doing recovery: scanned up to log sequence number 1349259594752
InnoDB: Doing recovery: scanned up to log sequence number 1349263940762
InnoDB: Transaction 677147354 was in the XA prepared state.
InnoDB: Transaction 677147359 was in the XA prepared state.
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 677147648
2019-09-06 14:14:41 6945 [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 222423295, file name mysql3306.001163
2019-09-06 14:14:42 6945 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2019-09-06 14:14:42 7fada5a2f700  InnoDB: Rollback of non-prepared transactions completed
2019-09-06 14:14:42 6945 [Note] InnoDB: Waiting for purge to start
2019-09-06 14:14:42 6945 [Note] InnoDB: 5.6.32 started; log sequence number 1349263940762
2019-09-06 14:14:42 6945 [Note] Recovering after a crash using /home/mysql/mysql-5.6.32_3306/data/mysql3306
2019-09-06 14:14:42 6945 [Note] Starting crash recovery...
2019-09-06 14:14:42 7fade6d4f720  InnoDB: Starting recovery for XA transactions...
2019-09-06 14:14:42 7fade6d4f720  InnoDB: Transaction 677147359 in prepared state after recovery
2019-09-06 14:14:42 7fade6d4f720  InnoDB: Transaction contains changes to 1 rows
2019-09-06 14:14:42 7fade6d4f720  InnoDB: Transaction 677147354 in prepared state after recovery
2019-09-06 14:14:42 7fade6d4f720  InnoDB: Transaction contains changes to 101 rows
2019-09-06 14:14:42 7fade6d4f720  InnoDB: 2 transactions in prepared state after recovery
2019-09-06 14:14:42 6945 [Note] Found 2 prepared transaction(s) in InnoDB
2019-09-06 14:14:42 6945 [Note] Crash recovery finished.
2019-09-06 14:14:42 6945 [Note] Server hostname (bind-address): '*'; port: 3306
2019-09-06 14:14:42 6945 [Note] IPv6 is available.
2019-09-06 14:14:42 6945 [Note]   - '::' resolves to '::';
2019-09-06 14:14:42 6945 [Note] Server socket created on IP: '::'.
2019-09-06 14:14:42 6945 [Note] Event Scheduler: Loaded 0 events
2019-09-06 14:14:42 6945 [Note] /home/mysql/mysql-5.6.32_3306/bin/mysqld: ready for connections.
Version: '5.6.32-log'  socket: '/home/mysql/mysql-5.6.32_3306/data/my3306.sock'  port: 3306  MySQL Community Server (GPL)

How to repeat:
I don't know how this problem came about, because now the environment can't go back to normal...

Dear,

Has anyone met it?
Although there is no evidence, I think it may be a hardware problem.
And I'm sure the disk still has storage.
As follow:$ df -hl
Filesystem      Size  Used Avail Use% Mounted on
/dev/sdb1       1.8T  1.4T  354G  80% /
tmpfs            32G  629M   31G   2% /dev/shm
/dev/sda2       190M   39M  142M  22% /boot
/dev/sda1       200M  264K  200M   1% /boot/efi
/dev/sdc1       1.8T   68M  1.7T   1% /new
Is there a solution?

Best Regards.
Leo.

Hi,

For start you really should upgrade to latest 5.6.

Now, this I/O error looks like a hardware error. Please check what dmesg and syslog have to say.

all best

Dear Bogdan Kecman,

Thanks for your reply!

We replaced the hard disk of the server first.But it seems to be the same problem that prevents the database from being copied.So we created a new database and restored the original backup.

According to what you said, I did the corresponding environment check.It has been confirmed that it is a hardware problem.

[root@$ ~]# badblocks -s -v /dev/sdb1 
正在检查从 0 到 1953513471的块  
Checking for bad blocks (read-only test): 968188800one, 3:22:11 elapsed
968188836one, 3:23:15 elapsed
968188837one, 3:23:36 elapsed
968188838one, 3:23:57 elapsed
968188839one, 3:24:19 elapsed
969017368one, 3:24:53 elapsed
969017424one, 3:25:36 elapsed
969017425one, 3:25:57 elapsed
969017426one, 3:26:19 elapsed
969017427one, 3:26:40 elapsed
完成
Pass completed, 10 bad blocks found.  
  
[root@$ ~]# dmesg | tail  
ata2.00: configured for UDMA/133
sd 1:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE  
sd 1:0:0:0: [sdb]  Sense Key : Medium Error [current] [descriptor]  
Descriptor sense data with sense descriptors (in hex):  
  72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00 
  73 84 18 a0 
sd 1:0:0:0: [sdb]  Add. Sense: Unrecovered read error - auto reallocate failed  
sd 1:0:0:0: [sdb] CDB: Read(10): 28 00 73 84 18 a0 00 00 08 00
end_request: I/O error, dev sdb, sector 1938036896
ata2: EH complete

[root@$ ~]# cat /var/log/messages |tail
Sep  9 10:27:36 $ kernel: ata2.00: configured for UDMA/133
Sep  9 10:27:36 $ kernel: sd 1:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Sep  9 10:27:36 $ kernel: sd 1:0:0:0: [sdb]  Sense Key : Medium Error [current] [descriptor]
Sep  9 10:27:36 $ kernel: Descriptor sense data with sense descriptors (in hex):
Sep  9 10:27:36 $ kernel:  72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Sep  9 10:27:36 $ kernel:  73 84 18 a0
Sep  9 10:27:36 $ kernel: sd 1:0:0:0: [sdb]  Add. Sense: Unrecovered read error - auto reallocate failed
Sep  9 10:27:36 $ kernel: sd 1:0:0:0: [sdb] CDB: Read(10): 28 00 73 84 18 a0 00 00 08 00
Sep  9 10:27:36 $ kernel: end_request: I/O error, dev sdb, sector 1938036896
Sep  9 10:27:36 $ kernel: ata2: EH complete 

Thanks again for your advice!

Best Regards,
Leo.

Thanks for the update, good luck with it.

all best