Re: Connection pool jdbc and listener logfile content

From: joel garry <joel-garry_at_home.com>
Date: Tue, 7 Dec 2010 08:58:39 -0800 (PST)
Message-ID: <402dfaa3-f350-41be-a227-a95d256a4c11_at_u25g2000pra.googlegroups.com>



On Dec 7, 12:55 am, "Radoulov, Dimitre" <cichomit..._at_gmail.com> wrote:
> Hi all,
>
> Environment
>
> Various applications that use jdbc connection pool:
> WebLogic 8 (and higher) and Tomcat 6 application servers,
> various versions of Oracle Database (from 9.2.0.7 to 10.2.0.4)
> on various platforms (RHEL 5.5, Solaris 9, Solari 10 etc).
>
> I'm trying to understand the meaning of the following entries in the
> listener log file (notice the 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 those applications use connection pools, v$session.logon_time
> reflect the time the connection pool was activated (usually tha
> application server start time) and the expected number of connections.
>
> So I'm trying to understand what those frequent entries in the listener
> log represent.
>
> Are these fresh new connections (I suppose they aren't) or they just
> represent the regular traffic that passes through the existing
> connections of the connection pool (if this is not the case, I don't
> understand why the port is changing (I know the listener redirects the
> client to a free port during the initial handshake, but I don't
> understand why this is happening after the connection pool is already up)
>
> Could this be sort of heart beat that doesn't use the connection pool?
>
> Unfortunately, in this case, auditing is disabled for application users
> so I don't have details in dba_audit_trail.
>
> These are some numbers from this particular logfile:
>
> $ 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
>
> The records are out of order but this is not relevant here,
> what I'm trying to understand the meaning of these 35 entries per minute.
>
> Thank you
> Dimitre
>
> P.S. I posted the same question on another forum, so for some users it's
> a duplicate, sorry.

Don't know much about jdbc, but those unique port id's mean new connection requests. If you don't have legitimate thousands of sessions, I'd be wondering if you have a poorly behaved application that gets a new connection for every statement. Googling about for too many connections, I noticed http://www.freelists.org/post/ora-apps-dba/JDBC-thin-client-connections,10 which seems to say there is something you can set to reuse more connections if you are using that sort of software. I'm sure I've seen other posts that wind up being improperly coded apps, but I don't know what you are doing.

jg

--
_at_home.com is bogus.
http://www.dailyfinance.com/story/salesforce-com-takes-a-shot-at-oracle-with-new-database-com/19749885/
Received on Tue Dec 07 2010 - 10:58:39 CST

Original text of this message