Re: Connection pool jdbc and listener logfile content

From: Radoulov, Dimitre <cichomitiko_at_gmail.com>
Date: Tue, 07 Dec 2010 19:21:14 +0100
Message-ID: <idltuq$266$1_at_news.eternal-september.org>

On 07/12/2010 17:58, joel garry wrote:
> On Dec 7, 12:55 am, "Radoulov, Dimitre"<cichomit..._at_gmail.com> wrote: [...]
>> 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

[...]
>>
>> 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.
>>

[...]

> 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.

I'll check how these FND_JDBC_* paramters map to jdbc native options, thank you!

I observe this behavior in various different java app servers environments on various customer sites and I don't find any abnormal resource usage because of it.

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

That makes me think that even though the OS port changes with every request, somehow those requests are using already established connection pool physical connections.

It would be great if someone else could run the above awk script (just use nawk on Solaris) in a different app environments that use jdbc connection pool, just to compare the numbers.

To be honest, I'm observing the same behavior on *all* our app environments and just noticed it on two customer sites that are managed by completely different app admins and developers.

And, of course, it's not impossible that there is a common misconfiguration ...

Thanks again

Regards
Dimitre Received on Tue Dec 07 2010 - 12:21:14 CST