Mailing-List: contact users-help@tomcat.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Tomcat Users List" <users@tomcat.apache.org>
Received-SPF: pass (nike.apache.org: domain of dckerber@verizon.net designates
 206.46.173.9 as permitted sender)
Message-id: <4A045686.9080107@verizon.net>
Date: Fri, 08 May 2009 11:57:58 -0400
From: David kerber <dckerber@verizon.net>
User-Agent: Thunderbird 2.0.0.21 (Windows/20090302)
MIME-version: 1.0
To: Tomcat Users List <users@tomcat.apache.org>
Subject: Re: Performance with many small requests
References: <4A034AFB.7070009@verizon.net><6715CF65287F8F408DA109EC03AC6C0DB
 CA5C4C67B@puma.melandra.net><BLU0-SMTP58D74B3D0B3D380D0DDEF3C5670@phx.gbl><
 4A036927.1000604@verizon.net><6715CF65287F8F408DA109EC03AC6C0DBCA5C4C680@pu
 ma.melandra.net><4A041E04.1030806@verizon.net><0AAE5AB84B013E45A7B61CB66943
 C172286168A9AF@USEA-EXCH7.na.uis.unisys.com><4A042331.6020406@verizon.net><
 0AAE5AB84B013E45A7B61CB66943C172286168AA91@USEA-EXCH7.na.uis.unisys.com>
 <4A042A07.60809@verizon.net>
 <0AAE5AB84B013E45A7B61CB66943C172286168AD3F@USEA-EXCH7.na.uis.unisys.com>
 <4A04349E.7080700@verizon.net> <4A045149.7080005@verizon.net>
 <6715CF65287F8F408DA109EC03AC6C0DBCA5C4C68A@puma.melandra.net>
In-reply-to: <6715CF65287F8F408DA109EC03AC6C0DBCA5C4C68A@puma.melandra.net>
Content-type: text/plain; charset=ISO-8859-1; format=flowed
Content-transfer-encoding: 7bit

Peter Crowther wrote:
>> From: David kerber [mailto:dckerber@verizon.net]
>> Now that I've got a thread dump, what am I looking for?
>>     
>
> You found it first time :-).  Now the hard part - fixing it.
>   
Yeah, that's what I figured!

>> I've got a
>> bunch of sections like this, pretty much all of which are waiting to
>> lock <0x057c73e0>.  Is there any way to figure out what that
>> object is?
>> I imagine it's the disk write, but can't figure out how to
>> tell for sure.
>>     
>
> It's the sync at the start of your method.
>
>   
>> [2009-05-08 10:43:24] [info] waiting for monitor entry
>> [2009-05-08 10:43:24] [info] [0x2739f000..0x2739fb64]
>> [2009-05-08 10:43:24] [info]     at
>> eddsrv.EddRcvr.doPost(EddRcvr.java:70)
>> [2009-05-08 10:43:24] [info]     - waiting to lock <0x057c73e0> (a
>> eddsrv.EddRcvr)
>>     
I also have quite a few blocks like this:

[2009-05-08 10:43:23] [info] "http-1024-Processor10"
[2009-05-08 10:43:23] [info] daemon
[2009-05-08 10:43:23] [info] prio=6 tid=0x271f1418
[2009-05-08 10:43:23] [info] nid=0xa74
[2009-05-08 10:43:23] [info] in Object.wait()
[2009-05-08 10:43:23] [info] [0x275df000..0x275dfae4]
[2009-05-08 10:43:23] [info]     at java.lang.Object.wait(Native Method)
[2009-05-08 10:43:23] [info]     at java.lang.Object.wait(Unknown Source)
[2009-05-08 10:43:23] [info]     at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
[2009-05-08 10:43:23] [info]     - locked <0x0510e6e0> (a 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
[2009-05-08 10:43:23] [info]     at java.lang.Thread.run(Unknown Source)
[2009-05-08 10:43:23] [info]

I assume these are just threads waiting for something to do (waiting for 
a request)?

>
> ... so they're all waiting to get the monitor on a eddsrv.EddRcvr, which is what the "synchronized" on your doPost method will lock on.
>   
Until you said that, I didn't even notice that I had what appear to be 
"double" synchronizations, making the method synchronized, and also 
having synchronized{} blocks inside it.  I assume I've been 
double-screwing myself all this time??

    protected synchronized void doPost(HttpServletRequest request, 
HttpServletResponse response )
            throws ServletException, IOException {
        synchronized ( criticalProcess ) {
            totalReqCount++;
            dailyReqCount++;
            processRequest( request, response, false );
        }
    }                


> If you say pretty much all are stuck there, then you have massive contention on that monitor.  Time to move to some finer-grained locking!  As a first step, I'd remove the synchronized from the method; I'd replace it with one lock around the counter updates (locked on one object) and another lock in your decrypt/log/respond code that's purely around the logging section (locked on a different object).  Then I'd re-evaluate - run, take another thread dump and see where the bottlenecks are now.  If they're anywhere, I'll bet they're around the logging code.
>   
Thanks!


D


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org