Relate JDBC connections to Oracle listener log file content -

environment

various applications use jdbc connection pool: weblogic 8 (and higher) , tomcat 6 application servers, various versions of oracle database (from 9.2.0.7 10.2.0.4) on various platforms (rhel 5.5, solaris 9, solari 10 etc).

i'm trying understand meaning of following entries in listener log file (notice frequency):

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 

all applications use connection pools, v$session.logon_time reflect time connection pool activated (usually tha application server start time) , expected number of connections.

so i'm trying understand frequent entries in listener log represent.

are these fresh new connections (i suppose aren't) or represent regular traffic passes through existing connections of connection pool (if not case, don't understand why port changing (i know listener redirects client free port during initial handshake, don't understand why happening after connection pool up)

could sort of heart beat doesn't use connection pool?

unfortunately, in case, auditing disabled application users don't have details in dba_audit_trail.

these numbers particular logfile:

$ tail -1000 listener_<my_sid>.log | awk 'end {     (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 

the records out of order not relevant here, i'm trying understand meaning of these 35 entries per minute.

i observe behavior in various different java app servers environments on various customer sites , don't find abnormal resource usage because of it.

the configured connection pool connections appear correctly in v$session: instance 50 x app node (min = max) see 50 connections x app node in v$session, v$session.logon_time reflects correctly time respective app node started.

that makes me think though os port changes every request, somehow requests using established connection pool physical connections.

it great if else run above awk script (just use nawk on solaris) in different app environments use jdbc connection pool, compare numbers.

to honest, i'm observing same behavior on all our app environments , noticed on 2 customer sites managed different app admins , developers.

and, of course, it's not impossible there common misconfiguration .

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

updates: 2011/02/28

more details 1 of environments.

• 4 wl instances (2 x node)
• 15 datasources

configuration:

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

the information below 1 of nodes (2 wl instances):

sql> select sysdate dual;  sysdate -------------------- 28/feb/2011 12:03:50   sql> select   username, machine, logon_time, count(1)   v$session   machine='node1' group   username, machine, logon_time order   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 {     (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 

i think make sense of need publish data source configuration application server in environment behaviour experienced.

the data source defines connection pool, , behaviour in terms of resizing etc.

i believe parameters used in data source definition proprietary, referring documentation jdbc provider may necessary - oracle , covers inthe weblogic documentation set.

hope helps.