# oracle监听自动重启问题记录

> 作者/来源: UCloud 运营管理员
> 发布时间: 2023-01-11T05:20:00.000Z
> 分类: 其他
> 标签: AI, 数据库, Linux
> 原文链接: http://117.50.162.249:3000/yun/articles/872

---

# oracle监听自动重启问题记录

> 来源: https://www.ucloud.cn/yun/130031.html
> 作者: IT那活儿
> 发布日期: 发布于2023-01-11 13:20

oracle监听自动重启问题记录

问题背景

有一段时间,某数据库在整点期间总是会发出几条连接失败的告警，如下

|  |
| --- |
| 2019-08-14 10:00:22, 29.211.?.?/??db can not connect, Warning from 5.223-mon\_pri\_conn.sh! |

分析过程

1.分析监听日志发现监听存在重启行为

|  |
| --- |
| 14-AUG-2019 10:00:16 \* (CONNECT\_DATA=(SERVICE\_NAME=dbinst1)(CID=(PROGRAM=sqlplus)(HOST=localhost.bss\_rh6\_dqjkj01\_35.176)(USER=ftpuser))) \* (ADDRESS=(PROTOCOL=tcp)(HOST=29.211.35.176)(PORT=19573)) \* establish \* dbinst1 \* 0 2019-08-14T10:00:17.907210+08:00 14-AUG-2019 10:00:17 \* (CONNECT\_DATA=(CID=(PROGRAM=)(HOST=\_\_jdbc\_\_)(USER=))(SERVICE\_NAME=dbinst1)) \* (ADDRESS=(PROTOCOL=tcp)(HOST=29.211.177.93)(PORT=63570)) \* establish \* dbinst1 \* 12518 TNS-12518: TNS:listener could not hand off client connection  **<-----10:00:17****监听开始异常**   TNS-12540: TNS:internal limit restriction exceeded 14-AUG-2019 10:00:17 \* (CONNECT\_DATA=(CID=(PROGRAM=)(HOST=\_\_jdbc\_\_)(USER=))(SERVICE\_NAME=dbinst1)) \* (ADDRESS=(PROTOCOL=tcp)(HOST=29.211.31.19)(PORT=43753)) \* establish \* dbinst1 \* 12518 TNS-12518: TNS:listener could not hand off client connection  TNS-12540: TNS:internal limit restriction exceeded 14-AUG-2019 10:00:17 \* (CONNECT\_DATA=(CID=(PROGRAM=)(HOST=\_\_jdbc\_\_)(USER=))(SERVICE\_NAME=dbinst1)) \* (ADDRESS=(PROTOCOL=tcp)(HOST=29.211.35.160)(PORT=15812)) \* establish \* dbinst1 \* 12518 TNS-12518: TNS:listener could not hand off client connection  TNS-12540: TNS:internal limit restriction exceeded  ....  14-AUG-2019 10:00:20 \* 12582 TNS-12582: TNS:invalid operation  TNS-12615: TNS:preempt error Error listening on: (ADDRESS=(PROTOCOL=ipc)(PARTIAL=yes)(QUEUESIZE=1)) 14-AUG-2019 10:00:21 \* establish \* 1159 TNS-01159: Internal connection limit has been reached; listener has shut down **<---****10:00:21****监听自动重启** TNS-12540: TNS:internal limit restriction exceeded No longer listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=29.211.16.112)(PORT=1521))) No longer listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=LISTENER))) No longer listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=29.211.16.131)(PORT=1521))) 2019-08-14T10:00:46.748331+08:00 System parameter file is /u01/app/12.2.0/grid/network/admin/listener.ora  ---异常前每秒短连接       11 14-AUG-2019 09:59:55       1 14-AUG-2019 09:59:56       1 14-AUG-2019 09:59:57       1 14-AUG-2019 09:59:59      18 14-AUG-2019 10:00:00      16 14-AUG-2019 10:00:01      13 14-AUG-2019 10:00:02       4 14-AUG-2019 10:00:03       6 14-AUG-2019 10:00:04      10 14-AUG-2019 10:00:05 **<-----****监听重启前存在大量的短连接行为**      53 14-AUG-2019 10:00:06      35 14-AUG-2019 10:00:07      47 14-AUG-2019 10:00:08      65 14-AUG-2019 10:00:09      105 14-AUG-2019 10:00:10      61 14-AUG-2019 10:00:11      31 14-AUG-2019 10:00:12       38 14-AUG-2019 10:00:13       5 14-AUG-2019 10:00:15       3 14-AUG-2019 10:00:16  **---****异常整个期间数据库等待事件正常，无明显高消耗** |

2.排查问题期间的os负载情况

|  |
| --- |
| OSWBB\_ARCHIVE\_DEST /u01/osw/oswbb/archive  zzz \*\*\*Wed Aug 14 10:00:10 CST 2019  procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----   r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st **31  6**      0 446655712  33212 1998720    0    0     1     3    0    0  1  1 98  0  0 **21 22**    0 446779968  35236 2008236    0    0 16300    96 259964 240440 11  3 83  3  0 **25 27**   0 446795360  37040 2020368    0    0 29096    48 235608 212541 11  3 82  4  0 zzz \*\*\*Wed Aug 14 10:00:24 CST 2019 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st **6 18**      0 443893696  72420 2204804    0    0     1     3    0    0  1  1 98  0  0 **13 12**     0 444055840  74432 2228936    0    0 22880    16 90258 85804  5  2 88  6  0 **6 17**    0 444172864  76036 2250128    0    0 19980   100 70041 61176  4  3 86  7  0 zzz \*\*\*Wed Aug 14 10:00:36 CST 2019 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st **6 20**     0 444360928  83052 2341764    0    0     1     3    0    0  1  1 98  0  0 **6 24**     0 444552928  83740 2098432    0    0  4436  1212 67242 61741  4  3 85  8  0 **125 220**      0 444898240  84812 2102292    0    0  3892  1544 174504 140362 12 13 55 19  0   **1.10****秒的时候** **r21 b22,** **该机器为****ssd****存储，平常****cpu-b****不到****5****，这里值已经有点异常**  **2.36****秒的时候出现****r 125 b220****，可能为监听重启积压导致，且异常时间点在监听重启后，不能确认是该问题导致故障****。** |

|  |
| --- |
| top - 10:00:36 up 288 days, 14:24,  2 users, **load average: 215.59**, 68.64, 29.25 Tasks: 8823 total,  15 running, 8808 sleeping,   0 stopped,   0 zombie Cpu(s):**8.4%us,  2.2%sy,  0.0%ni, 88.6%id,  0.6%wa**,  0.0%hi,  0.3%si,  0.0%st Mem:  1058551988k total, 611291252k used, 447260736k free,    87332k buffers Swap: 20971516k total,        0k used, 20971516k free,  2151908k cached    **1.****近一分钟****load****达到****215****，且较****5****分钟、****15****分钟****load****值出现直线上升。**  **2.****通常在****linux****平台** **load avg****为系统整体****load,** **包含** **cpu load, io load****等等****.****简单理解为** **R+D****状态的****process,****不代表****cpu****使用率，但****load****高一定存在某一方面的高负载情况****.** |

|  |
| --- |
| **重点排查一下异常期间的****ps** **数据，排除****S(sleep)****状态进程，可以看到大量的****IO****相关****D****进程**  [oracle@dbserver1 tmp]$ cat /tmp/ps1024.txt  | awk {print $1,$9,$10,$13,$14} | sort  | uniq -c **454 oracle filp\_o D oracledbinst11 (LOCAL=NO)****<-----****通过排查****filp\_o****为****linux** **打开文件的内核函数**      3 oracle get\_wr D oracledbinst11 (LOCAL=NO)      35 oracle lookup D oracledbinst11 (LOCAL=NO)       1 oracle lookup D ora\_m001\_dbinst11        1 oracle - R ps -aeo      16 oracle sync\_b D oracledbinst11 (LOCAL=NO)      1 root ? R /bin/netstat -ap       2 root ? R /bin/ps -p [oracle@dbserver1 tmp]$   [oracle@dbserver1 tmp]$ cat /tmp/ps1024.txt | grep 10:00 | awk {print $1,$9,$10,$11,$13,$14}  | sort | uniq -c **112 oracle filp\_o D 10:00:14 oracledbinst11 (LOCAL=NO)****<---------****10:00:14****建立的短连接** **112**  **115 oracle filp\_o D 10:00:15 oracledbinst11 (LOCAL=NO)****<---------****10:00:15****建立的短连接** **115** **积压的大量****短连接积处于****filp\_o** **状态，****io****可能存在异常**       75 oracle filp\_o D 10:00:16 oracledbinst11 (LOCAL=NO)       9 oracle filp\_o D 10:00:17 oracledbinst11 (LOCAL=NO)       1 oracle filp\_o D 10:00:36 oracledbinst11 (LOCAL=NO)       6 oracle lookup D 10:00:12 oracledbinst11 (LOCAL=NO)      38 oracle lookup D 10:00:13 oracledbinst11 (LOCAL=NO)      33 oracle lookup D 10:00:14 oracledbinst11 (LOCAL=NO)      33 oracle lookup D 10:00:15 oracledbinst11 (LOCAL=NO)      47 oracle lookup D 10:00:16 oracledbinst11 (LOCAL=NO)      17 oracle lookup D 10:00:17 oracledbinst11 (LOCAL=NO)       5 oracle lookup D 10:00:18 oracledbinst11 (LOCAL=NO)    **排查****ash****信息再次确认数据库负载较低，****io****响应也在毫秒级，无明显异常**  **使用****strace****跟踪测试建立连接期间，发现监听派生** **LOCAL=NO****进程后会读取大量的****ORACLE\_HOME****本地****lib****库****,****并进一步排查****/u01****文件系统状态**  [oracle@dbserver1 tmp]$  cat /tmp/stsqlplus.txt | grep 12.2.0/db 126319 open("/**u01**/app/oracle/product/12.2.0/db/lib/libsqlplus.so", O\_RDONLY) = 3 126319 open("/**u01**/app/oracle/product/12.2.0/db/lib/libclntsh.so.12.1", O\_RDONLY) = 3 126319 open("/**u01**/app/oracle/product/12.2.0/db/lib/libclntshcore.so.12.1", O\_RDONLY) = 3 126319 open("/**u01**/app/oracle/product/12.2.0/db/lib/libmql1.so", O\_RDONLY) = 3 126319 open("/**u01**/app/oracle/product/12.2.0/db/lib/libipc1.so", O\_RDONLY) = 3 126319 open("/**u01**/app/oracle/product/12.2.0/db/lib/libnnz12.so", O\_RDONLY) = 3    [oracle@dbserver1 tmp]$ lsblk  NAME            MAJ:MIN   RM   SIZE RO TYPE MOUNTPOINT sda               8:0      0 837.3G  0 disk  sda1            8:1      0     1G  0 part /boot sda2            8:2      0   100G  0 part / sda3            8:3      0    20G  0 part [SWAP] sda4            8:4      0     1K  0 part  sda5            8:5      0    20G  0 part /opt sda6            8:6      0    20G  0 part /usr sda7            8:7      0    20G  0 part /var/log **sda8            8:8      0   200G  0 part /u01**                                     **<-sda8** **本地盘挂在的****$ORACLE\_HOME,****核查是否存在问题**sdb               8:16     0   1.5T  0 disk   ..... sdo               8:224    0    30G  0 disk  sdp               8:240    0   300G  0 disk  sdq              65:0      0   300G  0 disk  sdr              65:16     0     2T  0 disk  asm!oradata-127 251:65025  0     2T  0 disk   zzz \*\*\*Wed Aug 14**10:00:11** CST 2019 avg-cpu:  %user   %nice %system %iowait  %steal   %idle       **11.35    0.00    2.83    3.21    0.00   82.61**  **<-------cpu****整体使用率不高，****iowait****整体也不高**Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util **sda 169.00     5.00  642.00    8.00 29000.00    52.00    89.39    10.19   35.69   2.54 100.00**  **<-------- sda-- /u01--ORACLE\_HOME****文件系统****IO****居高不下** **await****出现明显等待** sdb 0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 sdc 0.00     0.00  223.00   24.00  5640.00   452.00    49.33     0.08    0.33   0.25   6.10  zzz \*\*\*Wed Aug **14 10:00:24 CST** 2019 Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util **sda  176.00     1.00  656.00   25.00 23552.00   104.00    57.73    15.94   43.65   3.47 100.00**  **<--------sda-- /u01--ORACLE\_HOME****文件系统** **iowait****持续居高不下** sdb  0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 sdc  0.00     0.00   40.00   20.00   336.00   3 |

问题原因

1.通过与应用侧沟通了解到在整点期间app营业厅会推出抢购活动导致短连接明显的上升

2.主机管理员反馈由于本地盘RAID出现故障盘导致响应异常,以至于大量短连接挂死在ORACLE\_HOME的lib库读取上，达到监听队列上限值后引发监听重启.

改进措施

1.推进应用程序短连接进行连接池化整改。

2.更换本地盘为SSD存储提升ORACLE\_HOME的读写性能。

注:本次故障版本为oracle12.2，在oracle12c之后的版本中，数据库会持续写出大量的垃圾trace信息不仅影响IO性能且影响文件系统正常使用率,建议多带带指定diag目录以及使用SSD存储安装ORACLE\_HOME 。

![](https://ucloud-blog.cn-bj.ufileos.com/articles/130031/images/130031_000.png)

END

![](https://ucloud-blog.cn-bj.ufileos.com/articles/130031/images/130031_001.png)