Onderwerp: Tomcat soms traag met antwoorden

Beste WHT'ers,

Ik heb een setup met 2 tomcat servers die gelijk zijn geconfigureerd. Beide hebben een klein probleem, als ik een pagina open zit er af en toe een delay van tussen de 3 en de 8 seconde op voordat tomcat reageert.

Dit kan ik simuleren door simpel een wget te doen van de default tomcat index.jsp pagina. Ik heb echt geen idee wat dit veroorzaakt. Machine is niet super druk. Het gaat hier om een telefonie applicatie dus het is erg vervelend als er een paar seconde stilte valt zo af en toe. (4 a 5 op de 100 keer). Heeft iemand een idee wat het probleem kan zijn?

Code:

Attaching to process ID 1418, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_06-b05

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 2147483648 (2048.0MB)
   NewSize          = 4194304 (4.0MB)
   MaxNewSize       = 96468992 (92.0MB)
   OldSize          = 12582912 (12.0MB)
   NewRatio         = 15
   SurvivorRatio    = 1024
   PermSize         = 209715200 (200.0MB)
   MaxPermSize      = 419430400 (400.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 96403456 (91.9375MB)
   used     = 15409864 (14.695991516113281MB)
   free     = 80993592 (77.24150848388672MB)
   15.984763035881203% used
Eden Space:
   capacity = 96337920 (91.875MB)
   used     = 15409864 (14.695991516113281MB)
   free     = 80928056 (77.17900848388672MB)
   15.995637024340986% used
From Space:
   capacity = 65536 (0.0625MB)
   used     = 0 (0.0MB)
   free     = 65536 (0.0625MB)
   0.0% used
To Space:
   capacity = 65536 (0.0625MB)
   used     = 0 (0.0MB)
   free     = 65536 (0.0625MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 2051014656 (1956.0MB)
   used     = 171451808 (163.50918579101562MB)
   free     = 1879562848 (1792.4908142089844MB)
   8.35936532673904% used
Perm Generation:
   capacity = 209715200 (200.0MB)
   used     = 73634952 (70.22376251220703MB)
   free     = 136080248 (129.77623748779297MB)
   35.111881256103516% used

Code:

load averages:  0.54,  0.79,  0.75;                    up 18+04:55:53                                                      15:24:42
115 processes: 113 sleeping, 2 on cpu
CPU states: 98.7% idle,  1.0% user,  0.3% kernel,  0.0% iowait,  0.0% swap
Memory: 8064M phys mem, 4583M free mem, 2002M swap, 2002M free swap

   PID USERNAME LWP PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
  1418 sfe      182   0    0 2528M  546M cpu     65.7H 24.83% java
  1528 sfe       51  59    0  236M   93M sleep   78:35  2.95% java
  1049 mysql     74  59    0  136M  113M sleep  360:49  2.13% mysqld
  1061 root       1  59    0   18M   16M sleep   15:11  0.51% httpd
  3448 sfe        1  49    0 3336K 2656K cpu      0:00  0.49% top
  3451 nobody     1  59    0   18M 4400K sleep    0:00  0.28% httpd
  3449 nobody     1  59    0   18M 4400K sleep    0:00  0.24% httpd
  1145 noaccess  55  59    0  215M  127M sleep   37:15  0.24% java
  3452 nobody     1  59    0   18M 4400K sleep    0:00  0.21% httpd
  3455 nobody     1  59    0   18M 3672K sleep    0:00  0.14% httpd
  3456 nobody     1  59    0   18M 3672K sleep    0:00  0.14% httpd
  3450 sfe        1  53    2 1336K 1136K sleep    0:00  0.13% sleep
  3457 nobody     1  59    0   18M 3672K sleep    0:00  0.13% httpd
  3458 nobody     1  59    0   18M 3672K sleep    0:00  0.13% httpd
  3459 sfe        1  53    2 1336K 1136K sleep    0:00  0.13% sleep

Code:

Deze is goed

15:34:12 (62.92 MB/s) - `index.jsp.36' saved [8132/8132]

--15:34:17--  http://localhost:8080/index.jsp
           => `index.jsp.37'
Resolving localhost... 127.0.0.1, ::1
Connecting to localhost|127.0.0.1|:8080... connected.
HTTP request sent, awaiting response... 200 OK
Length: 8,132 (7.9K) [text/html]

100%[========================================================================================>] 8,132         --.--K/s

15:34:17 (63.59 MB/s) - `index.jsp.37' saved [8132/8132]


Deze heeft 4 seconde vertraging

--15:34:22--  http://localhost:8080/index.jsp
           => `index.jsp.38'
Resolving localhost... 127.0.0.1, ::1
Connecting to localhost|127.0.0.1|:8080... connected.
HTTP request sent, awaiting response... 200 OK
Length: 8,132 (7.9K) [text/html]

100%[========================================================================================>] 8,132         --.--K/s

15:34:26 (45.89 MB/s) - `index.jsp.38' saved [8132/8132]

zi je niet aan je max connections of max handles op het moment dat je moet wachten?
test eens als er niemand op de telefooncentrale zit ingelogd (of jij als enige) om te zien of het probleem zich nog steeds voordoet.

staat er ook niks in de error logs van tomcat? evt kun je loglevel verhogen naar debug (zie ook http://tomcat.apache.org/tomcat-5.5-doc/logging.html)

Dag bami82,

Er goed dat je een duidelijke en reproduceerbare test heb voor dit ongrijpbare probleem. Je schetst echter een probleem waar niemand zonder meer informatie een antwoord op kan geven. Maar dat mag de pret niet drukken. :-)

In de GC stats die je toont mis ik vooral het tijds-aspect. Het is een moment opname. Ze zien er wel ok uit, overigens. Ik verwacht dat het probleem niet daar zit, maar omdat dit een moment opname is kan ik dat niet met zekerheid zeggen.

Ik zou je willen aanraden om de Java-monitor probe te installeren. Je krijgt dan een grafiek van twee dagen met daarin het gedrag van je garbage collectors. Dat is een stuk duidelijker. Als je wilt zien hoe dat er uit ziet: http://java-monitor.com/livedemo.html en klik op een van de hosts om meer detail te zien. Installatie en wat meer uitleg staat op http://java-monitor.com/install.html . (bonus: gratis een mailtje als de server down gaat)

DISCLAIMER: ik ben de operator van Java-monitor.

Verder is de context van de Tomcat servers onduidelijk. Die index.jsp, wat doettie allemaal? Databases? Webservices? Alleen hello world?

Is het een shared machine? Virtuele machine waar een andere virtuele machine alle I/O van opvreet? VPS memory over-ge-commit waardoor de VPS moet worden ingeswapt voor jouw request?

Kees Jan

Hoi Kees Jan,

Bedankt voor je antwoord. Ik zal morgen is naar dat java-monitor kijken.

Het is een Sun Fire T2000, 8 cores, 32 threads, 8GB RAM, niet gevirtualiseerd. Draaien eigenlijk alleen tomcat apps op deze machine + mysql. De index.jsp is de default start pagina van tomcat dus geen db of iets dergelijks. MySQL draait alleen wat kleine db's en veroorzaakt ook weinig load verder.

I/O valt volgens mij allemaal wel mee maar zal ik morgen voor de zekerheid even checken.

Dag bami82,

Hier zijn wat checks die je met Java-monitor kunt doen. http://java-monitor.com/forum/showth...=newpost&t=560 hoewel jouw VM op 8 cores al automatisch de server JVM pakt.

Kees Jan

Vertragingen die zo lang duren hebben meestal met Garbage collection te maken (tenzij je server brak is, maar daar ga ik even niet vanuit).
Goede links om mee te starten :
http://java.sun.com/docs/hotspot/gc5.0/ergo5.html
http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html

Of je kan proberen met java6 die aardig wat intelligentie heeft ingebouwd om optimaal te gedragen.

Java IO is ook altijd interessant te bekijken : http://wiki.sdn.sap.com/wiki/display/Java/JPicus is een nuttige tool daarvoor

je kan misschien ook even kijken naar slechte/trage resolving op de server!

Oorspronkelijk geplaatst door wonko

je kan misschien ook even kijken naar slechte/trage resolving op de server!

Hoi Wonko, agenzien ik wgets do op localhost en daarmee het probleem kan simuleren lijkt dit me niet mogelijk.