【问题标题】：Relate JDBC connections to Oracle listener log file content将 JDBC 连接与 Oracle 侦听器日志文件内容相关联
【发布时间】：2010-12-20 14:07:27
【问题描述】：

环境

使用jdbc连接池的各种应用： WebLogic 8（及更高版本）和 Tomcat 6 应用服务器，各种版本的 Oracle 数据库（从 9.2.0.7 到 10.2.0.4）在各种平台上（RHEL 5.5、Solaris 9、Solari 10 等）。

我正在尝试了解侦听器日志文件中以下条目的含义（注意频率）：

07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59576)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59578)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59577)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59579)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59580)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59581)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59583)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59582)) * establish * <my_sid> * 0
07-DEC-2010 09:32:32 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59589)) * establish * <my_sid> * 0
07-DEC-2010 09:32:43 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59600)) * establish * <my_sid> * 0
07-DEC-2010 09:32:43 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59601)) * establish * <my_sid> * 0

所有这些应用程序都使用连接池，v$session.logon_time 反映了连接池被激活的时间（通常是应用程序服务器的启动时间）和预期的连接数。

所以我试图了解侦听器日志中的那些频繁条目代表什么。

这些是新的连接（我想它们不是）还是它们只是代表通过连接池的现有连接的常规流量（如果不是这种情况，我不明白为什么端口是改变（我知道监听器在初始握手期间将客户端重定向到一个空闲端口，但我不明白为什么在连接池已经启动后会发生这种情况）

这可能是一种不使用连接池的心跳吗？

很遗憾，在这种情况下，应用程序用户的审核功能被禁用所以我在 dba_audit_trail 中没有详细信息。

这些是来自这个特定日志文件的一些数字：

$ tail -1000 listener_<my_sid>.log | awk 'END {
    for (i in count)
  if (count[i] > 10)
    print i, count[i]
}
  /__jdbc__/ {
    sub(/:[^:]*$/, x, $2)
    count[$2]++
  }'
09:14 13
09:17 32
08:45 14
09:19 12
08:49 13
09:32 33
09:35 20
09:37 17
09:38 29
08:30 35
09:03 13
09:05 13
08:33 13
08:51 11
09:24 28

记录有问题，但这与这里无关，我试图理解每分钟这 35 个条目的含义。

我在不同客户站点的不同 java 应用服务器环境中观察到这种行为，我没有发现任何异常的资源使用情况。

配置的连接池连接正确显示在 v$session 中：例如，有 50 个应用程序节点（最小 = 最大）我在 v$session 中看到 50 个连接 x 应用程序节点，v$session.logon_time 正确反映了各自的时间应用节点已启动。

这让我觉得即使操作系统端口随每个请求而变化，但不知何故，这些请求正在使用已经建立的连接池物理连接。

如果其他人可以在使用 jdbc 连接池的不同应用程序环境中运行上述 awk 脚本（仅在 Solaris 上使用 nawk）来比较数字，那就太好了。

老实说，我在所有我们的应用环境中观察到相同的行为，只是在两个由完全不同的应用管理员和开发人员管理的客户网站上发现了这种行为。

当然，常见的错误配置也不是不可能的。

====================

更新：2011/02/28

其中一种环境的更多详细信息。

4 个 WL 实例（2 个节点）
15 个数据源

配置：

initial-capacity: 5
max-capacity:     varies, from 20 to 150
capacity-increment: varies, from 1 to 5
connection-reserve-timeout-seconds: 10
test-frequency-seconds: varies, from 120 to 240
inactive-connection-timeout-seconds: 0
seconds-to-trust-an-idle-pool-connection: 10

以下信息适用于其中一个节点（2 个 WL 实例）：

SQL> select sysdate from dual;

SYSDATE
--------------------
28/FEB/2011 12:03:50


SQL> select
  username, machine, logon_time, count(1)
from
  v$session
where
  machine='node1'
group by
  username, machine, logon_time
order by
  1,2,3;    2    3    4    5    6    7    8    9   10

USERNAME   MACHINE    LOGON_TIME             COUNT(1)
---------- ---------- -------------------- ----------
C_USER       node1     26/FEB/2011 20:25:01          1
C_USER       node1     26/FEB/2011 20:25:19          3
C_USER       node1     26/FEB/2011 20:25:20          2
C_USER       node1     26/FEB/2011 22:45:32          1
C_USER       node1     26/FEB/2011 22:45:46          5
C_USER       node1     27/FEB/2011 10:39:42          1
C_USER       node1     28/FEB/2011 09:25:16          1
C_USER       node1     28/FEB/2011 10:01:05          1
C_USER       node1     28/FEB/2011 10:01:06          1
C_USER       node1     28/FEB/2011 10:23:32          1
C_USER       node1     28/FEB/2011 10:23:33          6
C_USER       node1     28/FEB/2011 10:23:34          3
C_USER       node1     28/FEB/2011 10:36:09          1
C_USER       node1     28/FEB/2011 10:46:21          1
C_USER       node1     28/FEB/2011 11:00:17          1
C_USER       node1     28/FEB/2011 11:00:18          3
C_USER       node1     28/FEB/2011 11:16:26          2
C_USER       node1     28/FEB/2011 11:24:07          1
C_USER       node1     28/FEB/2011 11:24:08          1
C_USER       node1     28/FEB/2011 11:30:32          4
C_USER       node1     28/FEB/2011 11:30:33          1
C_USER       node1     28/FEB/2011 11:43:10          5
C_USER       node1     28/FEB/2011 11:50:36          9
C_USER       node1     28/FEB/2011 11:50:37          1
C_USER       node1     28/FEB/2011 11:54:16          2
C_USER       node1     28/FEB/2011 11:54:17          2
C_USER       node1     28/FEB/2011 12:01:52          2
C_USER       node1     28/FEB/2011 12:01:54          1
C_USER       node1     28/FEB/2011 12:01:55          4
S_USER       node1     26/FEB/2011 20:25:21          1
S_USER       node1     26/FEB/2011 22:45:47          1
W_USER       node1     23/FEB/2011 07:03:33          1
W_USER       node1     26/FEB/2011 20:25:05          1
W_USER       node1     26/FEB/2011 20:25:07          5
W_USER       node1     26/FEB/2011 20:25:15          3
W_USER       node1     26/FEB/2011 20:25:16          7
W_USER       node1     26/FEB/2011 20:25:17          1
W_USER       node1     26/FEB/2011 20:25:18          7
W_USER       node1     26/FEB/2011 20:25:19          3
W_USER       node1     26/FEB/2011 22:45:35          1
W_USER       node1     26/FEB/2011 22:45:37          4
W_USER       node1     26/FEB/2011 22:45:38          5
W_USER       node1     26/FEB/2011 22:45:42          5
W_USER       node1     26/FEB/2011 22:45:43          5
W_USER       node1     26/FEB/2011 22:45:44          3
W_USER       node1     26/FEB/2011 22:45:45          7
W_USER       node1     26/FEB/2011 22:45:46          1
W_USER       node1     27/FEB/2011 16:51:48          4

48 rows selected.

$ date
Mon Feb 28 12:19:35 CET 2011
$ tail -5000 listener_<snipped>.log | nawk 'END {
    for (i in count)
  if (count[i] > 10)
    print i, count[i]
}
  /__jdbc__.*HOST=<snipped>/ {
    sub(/:[^:]*$/, x, $2)
    count[$2]++
  }'| sort
07:29 13
08:57 13
09:09 18
09:24 18
09:29 27
09:32 13
09:37 17
09:51 12
10:01 13
10:06 27
10:12 17
10:19 13
10:20 12
10:22 17
10:23 16
10:35 17
11:00 13
11:21 18
11:24 17
11:38 13
11:43 32
11:50 13
11:54 23
12:01 15
12:05 17
12:10 28
12:17 18

【问题讨论】：

标签： oracle jdbc

【解决方案1】：

我认为要理解这一点，您还需要在经历此行为的环境中从应用服务器发布数据源配置。

数据源定义连接池，以及调整大小等方面的行为。

我相信数据源定义中使用的参数是专有的，因此可能需要参考 JDBC 提供程序的文档 - 这很可能是 Oracle 并且将包含在 Weblogic 文档集中。

希望这会有所帮助。

【讨论】：

谢谢！是的，连接池动态调整大小是一个可能的原因。