Mailing-List: contact commons-dev-help@jakarta.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Jakarta Commons Developers List" <commons-dev@jakarta.apache.org>
Date: 2 May 2003 21:07:18 -0000
Message-ID: <20030502210718.17676.qmail@nagoya.betaversion.org>
From: bugzilla@apache.org
To: commons-dev@jakarta.apache.org
Cc: 
Subject: DO NOT REPLY [Bug 19614] New:  -
    Poor performance under load

DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG 
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://nagoya.apache.org/bugzilla/show_bug.cgi?id=19614>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND 
INSERTED IN THE BUG DATABASE.

http://nagoya.apache.org/bugzilla/show_bug.cgi?id=19614

Poor performance under load

           Summary: Poor performance under load
           Product: Commons
           Version: 2.1 Final
          Platform: PC
        OS/Version: Linux
            Status: NEW
          Severity: Major
          Priority: Other
         Component: Dbcp
        AssignedTo: commons-dev@jakarta.apache.org
        ReportedBy: George.Lindholm@ubc.ca


I'm working with the JA-SIG uPortal under tomcat using 
Oracles thin driver. 

I've discovered that doing a Connection.close() was taking
longer and longer under heavy load.
I finally tracked it down to the synchronized statement 
in GenericObjectPool::returnObject() (after having removed the
synchronized attribute of the AbandonedPool methods).

I added some debugging statements like this:

    public void returnObject(Object obj) throws Exception {
      long startTime = System.currentTimeMillis();
        boolean success = true;
        if(_testOnReturn && !(_factory.validateObject(obj))) {
            success = false;
        } else {
            try {
                _factory.passivateObject(obj);
            } catch(Exception e) {
                success = false;
            }
        }

        boolean shouldDestroy = !success;

        long startTime3 = System.currentTimeMillis();
        synchronized(this) {
            long startTime2 = System.currentTimeMillis();
            _numActive--;
            if((_maxIdle > 0) && (_pool.size() >= _maxIdle)) {
                shouldDestroy = true;
            } else if(success) {
                _pool.addFirst(new ObjectTimestampPair(obj));
            }
            System.err.println("Thread.currentThread().getName() +
GenericObjectPool::returnObject:addFirst " + (System.currentTimeMillis() -
startTime2));
            startTime2 = System.currentTimeMillis();
            notifyAll(); // _numActive has changed
            System.err.println(Thread.currentThread().getName() +
"GenericObjectPool::returnObject:notify " + (System.currentTimeMillis() -
startTime2));
        }
        System.err.println(Thread.currentThread().getName() +
"GenericObjectPool::returnObject:synchronized " + (System.currentTimeMillis() -
startTime3));
        if(shouldDestroy) {
            try {
                _factory.destroyObject(obj);
                System.err.println("destroyed " + obj);
            } catch(Exception e) {
                // ignored
            }
        }
        System.err.println(Thread.currentThread().getName() +
"GenericObjectPool::returnObject: " + (System.currentTimeMillis() - startTime) +
":: Active: " + _numActive + ", poolSize: " + _pool.size());


Here is a short example of the times I'm seeing under load:

HttpProcessor[8090][26]GenericObjectPool::returnObject:addFirst 0
HttpProcessor[8090][26]GenericObjectPool::returnObject:notify 0
HttpProcessor[8090][26]GenericObjectPool::returnObject:synchronized 8158
HttpProcessor[8090][26]GenericObjectPool::returnObject: 8158:: Active: 25,
poolSize: 3
HttpProcessor[8090][26]AbandonedPool::returnObject: 8158:: Active: 25, poolSize: 3
HttpProcessor[8090][26]PoolableConnection::returnObject: 8158
HttpProcessor[8090][25]GenericObjectPool::returnObject:addFirst 0
HttpProcessor[8090][25]GenericObjectPool::returnObject:notify 0
HttpProcessor[8090][25]GenericObjectPool::returnObject:synchronized 8497
HttpProcessor[8090][25]GenericObjectPool::returnObject: 8497:: Active: 28,
poolSize: 1
HttpProcessor[8090][25]AbandonedPool::returnObject: 8497:: Active: 28, poolSize: 1
HttpProcessor[8090][25]PoolableConnection::returnObject: 8497
HttpProcessor[8090][23]GenericObjectPool::returnObject:addFirst 0
HttpProcessor[8090][23]GenericObjectPool::returnObject:notify 0
HttpProcessor[8090][23]GenericObjectPool::returnObject:synchronized 8340
HttpProcessor[8090][23]GenericObjectPool::returnObject: 8342:: Active: 28,
poolSize: 1
HttpProcessor[8090][23]AbandonedPool::returnObject: 8342:: Active: 28, poolSize: 1
HttpProcessor[8090][23]PoolableConnection::returnObject: 8342
HttpProcessor[8090][2]GenericObjectPool::returnObject:addFirst 0
HttpProcessor[8090][2]GenericObjectPool::returnObject:notify 0
HttpProcessor[8090][2]GenericObjectPool::returnObject:synchronized 8333
HttpProcessor[8090][2]GenericObjectPool::returnObject: 8334:: Active: 27,
poolSize: 2
HttpProcessor[8090][2]AbandonedPool::returnObject: 8334:: Active: 27, poolSize: 2
HttpProcessor[8090][2]PoolableConnection::returnObject: 8334


java version "1.4.1_02"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_02-b06)
Java HotSpot(TM) Client VM (build 1.4.1_02-b06, mixed mode)


And is it really necessary to notifyAll()? Why not use notify() instead
since the effect would be the same in this use?
Thanks


   George

---------------------------------------------------------------------
To unsubscribe, e-mail: commons-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: commons-dev-help@jakarta.apache.org