oracle数据库总自动重启问题吗,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  

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 

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/archivezzz ***Wed Aug 14 10:00:10 CST 2019procs ———–memory———- —swap– —–io—- –system– —–cpu—– r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st31  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)

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)

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                                    

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 1410:00:11 CST 2019

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

11.35    0.00    2.83    3.21    0.00   82.61

sda 169.00     5.00  642.00    8.00 29000.00    52.00    89.39    10.19   35.69   2.54 100.00

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

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 。