我们在处理数据库的问题的时候，有时在数据库端看不到异常的等待，但是应用却报连接异常。
这种情况，有可能是在压力还没有传递到数据库，在网络这层已经发生问题了。如连接风暴，此时的数据库listener的进程已经忙不过来，将连接丢弃。（在主机层面可以看到tcpListeneDrop增加）。
我们如果去看普通的listener日志，看到的东西是这样的：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
…… 24-FEB-2017 09:11:03 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=sqlplus@mynwdb)(HOST=mynwdb)(USER=appl))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65184)) * establish * mynwdb * 0 24-FEB-2017 09:11:06 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=STANDARD)(HOST=mynwdb)(USER=appl))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65186)) * establish * mynwdb * 0 24-FEB-2017 09:11:10 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=STANDARD)(HOST=mynwdb)(USER=appl))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65188)) * establish * mynwdb * 0 24-FEB-2017 09:11:10 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=STANDARD)(HOST=mynwdb)(USER=appl))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65189)) * establish * mynwdb * 0 Fri Feb 24 09:11:14 2017 24-FEB-2017 09:11:14 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65194)) * establish * mynwdb * 0 24-FEB-2017 09:11:14 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65195)) * establish * mynwdb * 0 24-FEB-2017 09:11:15 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65196)) * establish * mynwdb * 0 24-FEB-2017 09:11:15 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65197)) * establish * mynwdb * 0 24-FEB-2017 09:11:15 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65198)) * establish * mynwdb * 0 24-FEB-2017 09:11:15 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65199)) * establish * mynwdb * 0 24-FEB-2017 09:11:15 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65200)) * establish * mynwdb * 0 24-FEB-2017 09:11:15 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65201)) * establish * mynwdb * 0 24-FEB-2017 09:11:16 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65202)) * establish * mynwdb * 0 24-FEB-2017 09:11:16 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65203)) * establish * mynwdb * 0 24-FEB-2017 09:11:16 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65204)) * establish * mynwdb * 0 24-FEB-2017 09:11:16 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65205)) * establish * mynwdb * 0 24-FEB-2017 09:11:16 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65206)) * establish * mynwdb * 0 24-FEB-2017 09:11:17 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65207)) * establish * mynwdb * 0 24-FEB-2017 09:11:17 * (CONNECT_DATA=(SID=mynwdb)(CID=(PROGRAM=INVMGR)(HOST=mynwdb)(USER=nusr))) * (ADDRESS=(PROTOCOL=tcp)(HOST=11.22.3.123)(PORT=65208)) * establish * mynwdb * 0 …… |
这样我们会看的比较晕，不知道里面的连接数变化。
有一个listener日志的解析利器，可以分析到这种类型的问题。见附件。
用法:lsnr_analyzer.pl -t ‘time rexge’ [-h] filename
如，我们要分析24-FEB-2017 09:30~09:59的连接情况，可以如下操作：
|
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 |
[ora@mynwdb trace]$ lsnr_analyzer.pl -t '24-FEB-2017 09:[3-5][0-9]' mynwdb_cut1.log 24-FEB-2017 09:30 => Total:37 24-FEB-2017 09:31 => Total:50 24-FEB-2017 09:32 => Total:17 24-FEB-2017 09:33 => Total:16 24-FEB-2017 09:34 => Total:19 24-FEB-2017 09:35 => Total:16 24-FEB-2017 09:36 => Total:17 24-FEB-2017 09:37 => Total:16 24-FEB-2017 09:38 => Total:13 24-FEB-2017 09:39 => Total:29 24-FEB-2017 09:40 => Total:43 24-FEB-2017 09:41 => Total:38 24-FEB-2017 09:42 => Total:17 24-FEB-2017 09:43 => Total:16 24-FEB-2017 09:44 => Total:42 24-FEB-2017 09:45 => Total:21 24-FEB-2017 09:46 => Total:16 24-FEB-2017 09:47 => Total:15 24-FEB-2017 09:48 => Total:12 24-FEB-2017 09:49 => Total:25 24-FEB-2017 09:50 => Total:47 24-FEB-2017 09:51 => Total:41 24-FEB-2017 09:52 => Total:21 24-FEB-2017 09:53 => Total:12 24-FEB-2017 09:54 => Total:17 24-FEB-2017 09:55 => Total:16 24-FEB-2017 09:56 => Total:20 24-FEB-2017 09:57 => Total:17 24-FEB-2017 09:58 => Total:17 24-FEB-2017 09:59 => Total:21 [ora@mynwdb trace]$ |
可以看到，在09:31的时候，有个连接数的增加，到了一分钟50个连接。
我们可以加-h的参数，breakdown具体是哪些主机连接过来的：
|
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 |
[ora@mynwdb trace]$ lsnr_analyzer.pl -t '24-FEB-2017 09:[3-5][0-9]' -h mynwdb_cut1.log 24-FEB-2017 09:30 => Total:37 11.22.3.123 37 24-FEB-2017 09:31 => Total:50 22.3.4.111 1 11.22.3.123 49 24-FEB-2017 09:32 => Total:17 10.8.1.218 1 11.22.3.123 16 24-FEB-2017 09:33 => Total:16 11.22.3.123 16 24-FEB-2017 09:34 => Total:19 11.22.3.123 19 24-FEB-2017 09:35 => Total:16 11.22.3.123 16 24-FEB-2017 09:36 => Total:17 22.3.4.111 1 11.22.3.123 16 24-FEB-2017 09:37 => Total:16 12.5.6.221 1 11.22.3.123 15 24-FEB-2017 09:38 => Total:13 11.22.3.123 13 24-FEB-2017 09:39 => Total:29 11.22.3.123 29 24-FEB-2017 09:40 => Total:43 11.22.3.123 43 24-FEB-2017 09:41 => Total:38 22.3.4.111 1 11.22.3.123 37 24-FEB-2017 09:42 => Total:17 12.5.6.221 1 11.22.3.123 16 24-FEB-2017 09:43 => Total:16 11.22.3.123 16 24-FEB-2017 09:44 => Total:42 11.22.3.123 42 24-FEB-2017 09:45 => Total:21 11.22.3.123 21 24-FEB-2017 09:46 => Total:16 22.3.4.111 1 11.22.3.123 15 24-FEB-2017 09:47 => Total:15 12.5.6.221 1 11.22.3.123 14 24-FEB-2017 09:48 => Total:12 11.22.3.123 12 24-FEB-2017 09:49 => Total:25 11.22.3.123 25 24-FEB-2017 09:50 => Total:47 11.22.3.123 47 24-FEB-2017 09:51 => Total:41 22.3.4.111 1 11.22.3.123 40 24-FEB-2017 09:52 => Total:21 12.5.6.221 1 11.22.3.123 20 24-FEB-2017 09:53 => Total:12 11.22.3.123 12 24-FEB-2017 09:54 => Total:17 11.22.3.123 17 24-FEB-2017 09:55 => Total:16 11.22.3.123 16 24-FEB-2017 09:56 => Total:20 22.3.4.111 1 11.22.3.123 19 24-FEB-2017 09:57 => Total:17 12.5.6.221 1 11.22.3.123 16 24-FEB-2017 09:58 => Total:17 11.22.3.123 17 24-FEB-2017 09:59 => Total:21 11.22.3.123 21 [ora@mynwdb trace]$ |
可以看到09:30的时候，是来自11.22.3.123有49个连接，来自22.3.4.111有1个连接。
注1：lsnr_analyzer.pl 是用来分析已经establish的连接，如果是其他连接，不统计在内。
注2：lsnr_analyzer.pl 的统计比较消耗cpu，30万行的listener日志分析大约1秒出结果，300万行的listener日志分析大约6秒出结果。所以如果listener日志比较大，建议tail剪切后统计。
对于已经出现tcpListenDrop的情况，我们分几种情况分析：
（1）如果是突然的连接风暴，需要控制前端的连接，如weblogic中间件逐台启动，而不是同时启动；
（2）如果一直连接数很高，导致listener无法处理，就需要拆分listener，如按照端口拆分。
附件：lsnr_analyzer.pl
lsnr_analyzer