最近后台服务突然出现了连接池不够用的情况，不定时的会抛出java.lang.IllegalStateException: Pool not open
2019-09-06 08:21:52.701->java.lang.IllegalStateException: Pool not open java.lang.IllegalStateException: Pool not open at org.apache.commons.pool.BaseObjectPool.assertOpen(BaseObjectPool.java:78)
1.由于业务量与系统架构都没有发生变化，初步怀疑是最近开发的代码有问题：
怀疑 没有及时的回收资源，造成连接池泄漏。 在经过对代码的再次check之后，未发现任何问题。
2.检查数据库配置参数
-- 查看线程 SHOW PROCESSLIST; SHOW STATUS LIKE 'Threads%'; ###+-------------------+-------+ ###| Variable_name | Value | ###+-------------------+-------+ ###| Threads_cached | 10 | ###| Threads_connected | 326 | ###这个数值指的是打开的连接数 ###| Threads_created | 653 | ###| Threads_running | 16 | ###这个数值指的是激活的连接数，这个数值一般远低于connected数值 ###+-------------------+-------+ -- Threads_connected 跟show processlist结果相同，表示当前连接数。准确的来说，Threads_running是代表当前并发数 -- 这是是查询数据库当前设置的最大连接数 SHOW VARIABLES LIKE '%max_connections%'; ###+-----------------+-------+ ###| Variable_name | Value | ###+-----------------+-------+ ###| max_connections | 2000 | ###+-----------------+-------+
从数据库的配置来看，没有任何问题。 只有从线程上发现，每次服务没有连接池之后，数据库的线程也就是激活的连接数会很少，明显少于我们的后台服务所需要的连接数。初步怀疑是与数据库有关。怀疑有人重启了数据库。
3.查看数据库的日志 ***.err
获取到了 .err 数据库日志后，查看确实是数据库有重启的记录。但是并非人为重启了数据库。服务也已经恢复了。
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)
作为一个小白，自然而然的想到是否是由于磁盘空间不足导致－＿－然而并不是．．．
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
到这里其实我有点崩溃－＿－在冥思(bai)苦想(du)完无果之后，于是请教了MySQL Team．．．
>>> 小白悲惨的心路历程 : https://bugs.mysql.com/bug.php?id=96776
听从了他们的建议，我开始了漫长的磁盘坏道检查，最后发现果然磁盘出现了坏道（口吐莲花＊＊＊服务器）
[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
于是跟老大汇报了问题，申请了新的磁盘，迁移了数据库存储的磁盘，最终解决了此次问题．．．
