dev@grizzly.java.net

locking question

From: <rama.rama_at_tiscali.it>
Date: Fri, 6 Mar 2009 15:15:04 +0100 (CET)

Yo!

I have a question for you :)

after profiling my code, i have
noticed something that i don't understand.

This is a list of locks
that happen when the webserver is under load.
(sorry for the poor
formattation)


<GROUP ONE>
I am just curious to understand what this
problem can be.
The waiting/owner threads are blocked/waiting on
threadpoolexecutor$worker.run();
My first idea was that some req went
queued, but this is not true, because i have put maxthread >
test_concurrency
(test_concurrency = 45, maxthread = 64) [you can see
that the value are correctly configured, because on
the follow logs you
will get some workerthread with high id]
The avg locking time as you
can see is more or less 400ms that is a lot for a ws (means that some

request required 400ms+<normal elaboration time> to be executed)

--------------------------------------
Time Duration Type Monitor ID
Monitor class Waiting thread Owning thread
5:40.495 456 ms Blocked 34
java.util.concurrent.locks.ReentrantLock$NonfairSync http2480-
WorkerThread(32) [Grizzly] http2480-WorkerThread(18) [Grizzly]
5:40.481
470 ms Blocked 34 java.util.concurrent.locks.ReentrantLock$NonfairSync
http2480-WorkerThread(1) [Grizzly] http2480-WorkerThread(18) [Grizzly]

5:40.470 481 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync http2480-WorkerThread(61) [Grizzly] http2480-
WorkerThread(18) [Grizzly]
5:40.371 580 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync http2480-WorkerThread(24)
[Grizzly] http2480-WorkerThread(18) [Grizzly]
6:23.789 438 ms Blocked
34 java.util.concurrent.locks.ReentrantLock$NonfairSync http2480-
WorkerThread(45) [Grizzly] http2480-WorkerThread(33) [Grizzly]
6:02.245
455 ms Blocked 34 java.util.concurrent.locks.ReentrantLock$NonfairSync
http2480-WorkerThread(59) [Grizzly] http2480-WorkerThread(33) [Grizzly]

6:23.878 436 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync http2480-WorkerThread(0) [Grizzly] http2480-
WorkerThread(34) [Grizzly]
7:19.913 402 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync http2480-WorkerThread(16)
[Grizzly] http2480-WorkerThread(39) [Grizzly]
7:19.884 430 ms Blocked
34 java.util.concurrent.locks.ReentrantLock$NonfairSync http2480-
WorkerThread(34) [Grizzly] http2480-WorkerThread(39) [Grizzly]
7:19.857
457 ms Blocked 34 java.util.concurrent.locks.ReentrantLock$NonfairSync
http2480-WorkerThread(23) [Grizzly] http2480-WorkerThread(39) [Grizzly]

7:19.850 463 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync http2480-WorkerThread(44) [Grizzly] http2480-
WorkerThread(39) [Grizzly]
7:19.831 481 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync http2480-WorkerThread(59)
[Grizzly] http2480-WorkerThread(39) [Grizzly]
8:20.366 411 ms Blocked
34 java.util.concurrent.locks.ReentrantLock$NonfairSync http2480-
WorkerThread(40) [Grizzly] http2480-WorkerThread(54) [Grizzly]
8:20.300
477 ms Blocked 34 java.util.concurrent.locks.ReentrantLock$NonfairSync
http2480-WorkerThread(25) [Grizzly] http2480-WorkerThread(54) [Grizzly]

8:20.298 478 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync http2480-WorkerThread(32) [Grizzly] http2480-
WorkerThread(54) [Grizzly]
8:20.219 558 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync http2480-WorkerThread(56)
[Grizzly] http2480-WorkerThread(54) [Grizzly]
8:20.216 543 ms Blocked
34 java.util.concurrent.locks.ReentrantLock$NonfairSync http2480-
WorkerThread(17) [Grizzly] http2480-WorkerThread(54) [Grizzly]
7:52.036
1153 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync http2480-WorkerThread(27) [Grizzly] http2480-
WorkerThread(60) [Grizzly]
7:52.036 1154 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync http2480-WorkerThread(8)
[Grizzly] http2480-WorkerThread(60) [Grizzly]
6:02.289 413 ms Blocked
34 java.util.concurrent.locks.ReentrantLock$NonfairSync http2480-
WorkerThread(28) [Grizzly] http2480-WorkerThread(7) [Grizzly]
6:02.272
428 ms Blocked 34 java.util.concurrent.locks.ReentrantLock$NonfairSync
http2480-WorkerThread(36) [Grizzly] http2480-WorkerThread(7) [Grizzly]

6:02.271 429 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync http2480-WorkerThread(51) [Grizzly] http2480-
WorkerThread(7) [Grizzly]


<GROUP TWO>
blocked/waiting on com.sun.
grizzly.Controller.run()
Same of above, i need some clue to understand
better what's up :)
even there the locking time is pretty high, with
450 of avg.
------------------
845 468 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync GrizzlyReadController-5
[main] http2480-WorkerThread(39) [Grizzly]
7:19.845 468 ms Blocked 34
java.util.concurrent.locks.ReentrantLock$NonfairSync
GrizzlyReadController-1 [main] http2480-WorkerThread(39) [Grizzly]
7:
19.836 477 ms Blocked 34 java.util.concurrent.locks.
ReentrantLock$NonfairSync GrizzlyReadController-2 [main] http2480-
WorkerThread(39) [Grizzly]
7:19.836 477 ms Blocked 34 java.util.
concurrent.locks.ReentrantLock$NonfairSync GrizzlyReadController-3
[main] http2480-WorkerThread(39) [Grizzly]



--------
GrizzlyWS
configuration
DefaultThreadPool.DEFAULT_MAX_THREAD_COUNT=64;

DefaultThreadPool.DEFAULT_MIN_THREAD_COUNT=64;
ws = new GrizzlyWS
ws.
getSelectorThread().setSelectorReadThreadsCount(6);
ws.setMaxThreads
(64) //probably unuseful? right now the only way to set maxthreads is
to change
the defthreadpool min thread to match the maxthread, and
having all threads spawned when ws start up



Tnx for your advices :)


Con Tiscali Tutto Incluso telefoni e navighi senza limiti A SOLI €10 AL MESE FINO ALL’ESTATE. Attiva entro il 12/03/09! http://abbonati.tiscali.it/promo/tuttoincluso/