tomcat prozesse bleiben hängen

[Ulrik Hoffmann]

Moin zusammen,

ich habe ein Problem mit einer "geerbten" Intranet-Anwendung, bei der ich
folgendes Verhalten beobachte:

- zunächst verhält sich die Anwendung normal und verarbeitet ca. 1
Anfrage pro Sekunde

- kommt die Kombination "etwas längere Abfragezeit" und "ungeduldige"
Nutzer zusammen, klicken die Leute (Rheinländer ;-)) mehrfach auf die
Links in der Hoffnung, die Seiten würden schneller ausgeliefert.

- bei diesen Mehrfachrequests bleiben auf der Linux-Maschine Prozesse
hängen, ein "ps -ef | grep java | wc -l" liefert in etwa eine der Anzahl
nicht zu Ende gelaufenenen Requests höheren Wert.

- diese Prozesse werden nicht wieder abgebaut und bleiben bestehen

- irgendwann läuft die Anwendung gegen die im Connector eingestellten
"maxThreads" und antwortet zunächst schleppender, irgendwann gar nicht mehr

- Fehlermeldungen werden nicht protokolliert :-(


Die Anwendungen benutzt JSPs/Servlet und läuft gegen eine Oracle 10GR2
Datenbank. Das Verhalten wurde sowohl unter Tomcat 5.0.28/jdk1.4 und
5.5.14/jdk1.5 beobachtet, sowohl unter Suse 8.2 native und einem
gentoo-Linux unter VMware.

Die Datenbank-Transaktionen werden sauber geschlossen (open-cursors sinkt
nach Abarbeitung der Abfragen wieder auf normal).

Das Verhalten ist durch "Trommelfeuer" auf Aktualisieren-Button jederzeit
reproduzierbar.

Folgende Lösungen ziehe ich in Erwägung
- Erhöhung der maxThreads im Connector (derzeit 300) verschiebt das
Problem nach hinten. Was ist da eigentlich die Höchstgrenze?
- Wechsel auf Windows (*Nackenhaarsträub*), denn dort ist das Verhalten
definitiv nicht reproduzzierbar
- Umbau der kritischen Masken (serialisieren?)

Hat jemand von Euch ne Idee, woran das liegen könnte und kann mir einen
Tipp geben, wonach ich suchen soll?

Vielen Dank und viele Grüße
Ulrik

[Achim Peters]

Post by Ulrik Hoffmann
ich habe ein Problem mit einer "geerbten" Intranet-Anwendung, bei der
- bei diesen Mehrfachrequests bleiben auf der Linux-Maschine Prozesse
hängen, ein "ps -ef | grep java | wc -l" liefert in etwa eine der
Anzahl nicht zu Ende gelaufenenen Requests höheren Wert.

Wie sehen diese von ps gelisteten java-Prozesse denn vollständig aus
(Kommandozeilenoptionen, insbesondere main-Klasse)?

Bye
Achim

[Ulrik Hoffmann]

Post by Achim Peters

Post by Ulrik Hoffmann
- bei diesen Mehrfachrequests bleiben auf der Linux-Maschine Prozesse
hängen, ein "ps -ef | grep java | wc -l" liefert in etwa eine der
Anzahl nicht zu Ende gelaufenenen Requests höheren Wert.

Wie sehen diese von ps gelisteten java-Prozesse denn vollständig aus
(Kommandozeilenoptionen, insbesondere main-Klasse)?

Hi Achim,

z.B. so

root 13495 9759 0 14:33 ? 00:00:00
/opt/blackdown-jdk-1.4.1/bin/jav
a -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.util.
logging.config.file=/opt/tomcat5/conf/logging.properties
-Djava.endorsed.dirs=/o
pt/tomcat5/common/endorsed -classpath
:/opt/tomcat5/bin/bootstrap.jar:/opt/tomca
t5/bin/commons-logging-api.jar -Dcatalina.base=/opt/tomcat5
-Dcatalina.home=/opt
/tomcat5 -Djava.io.tmpdir=/opt/tomcat5/temp
org.apache.catalina.startup.Bootstra
p start


Gruss
Ulrik

[Achim Peters]

Post by Ulrik Hoffmann

Post by Achim Peters

Post by Ulrik Hoffmann
- bei diesen Mehrfachrequests bleiben auf der Linux-Maschine Prozesse
hängen, ein "ps -ef | grep java | wc -l" liefert in etwa eine der
Anzahl nicht zu Ende gelaufenenen Requests höheren Wert.

Wie sehen diese von ps gelisteten java-Prozesse denn vollständig aus
(Kommandozeilenoptionen, insbesondere main-Klasse)?

z.B. so
root 13495 9759 0 14:33 ? 00:00:00
/opt/blackdown-jdk-1.4.1/bin/jav
a -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.util.
logging.config.file=/opt/tomcat5/conf/logging.properties
-Djava.endorsed.dirs=/o
pt/tomcat5/common/endorsed -classpath
:/opt/tomcat5/bin/bootstrap.jar:/opt/tomca
t5/bin/commons-logging-api.jar -Dcatalina.base=/opt/tomcat5
-Dcatalina.home=/opt
/tomcat5 -Djava.io.tmpdir=/opt/tomcat5/temp
org.apache.catalina.startup.Bootstra
p start

Ich habe noch nicht so viele Tomcats aufgesetzt, aber ist das nicht eher
ungewöhnlich, dass jeder HTTP-Request einen neuen Tomcat startet? Das
wird doch normal über eine VM und dann Threads gehandelt?

Bye
Achim

[Markus Schönhaber]

Post by Achim Peters

Post by Ulrik Hoffmann
z.B. so
root 13495 9759 0 14:33 ? 00:00:00
/opt/blackdown-jdk-1.4.1/bin/jav
a -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.util.
logging.config.file=/opt/tomcat5/conf/logging.properties
-Djava.endorsed.dirs=/o
pt/tomcat5/common/endorsed -classpath
:/opt/tomcat5/bin/bootstrap.jar:/opt/tomca
t5/bin/commons-logging-api.jar -Dcatalina.base=/opt/tomcat5
-Dcatalina.home=/opt
/tomcat5 -Djava.io.tmpdir=/opt/tomcat5/temp
org.apache.catalina.startup.Bootstra
p start

Ich habe noch nicht so viele Tomcats aufgesetzt, aber ist das nicht eher
ungewöhnlich, dass jeder HTTP-Request einen neuen Tomcat startet? Das
wird doch normal über eine VM und dann Threads gehandelt?

Es sind im zweifel keine neuen Prozesse sondern Threads. IIRC gibt ps auf
einem System mit einer glibc, die linuxthreads benutzt, Threads wie
Prozesse aus.

Zur Frage von Ulrik: Als erstes würde ich testen, ob das Problerm auch mit
einer aktuellen Java-VM (insbesondere der von Sun) noch auftritt.

Gruß
mks

[Ulrik Hoffmann]

Post by Markus Schönhaber
Zur Frage von Ulrik: Als erstes würde ich testen, ob das Problerm auch mit
einer aktuellen Java-VM (insbesondere der von Sun) noch auftritt.

ja, tut es.
Anderer tomcat, anderer User, andere VM, anderes Linux, gleiches Problem:


oracle 19255 18846 0 Jan03 pts/0 00:00:00
/home/oracle/jdk1.5.0_06//bin/java
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.util.logging.config.file=/home/oracle/apache-tomcat-5.5.14/conf/logging.properties
-Djava.endorsed.dirs=/home/oracle/apache-tomcat-5.5.14/common/endorsed
-classpath
:/home/oracle/apache-tomcat-5.5.14/bin/bootstrap.jar:/home/oracle/apache-tomcat-5.5.14/bin/commons-logging-api.jar
-Dcatalina.base=/home/oracle/apache-tomcat-5.5.14
-Dcatalina.home=/home/oracle/apache-tomcat-5.5.14
-Djava.io.tmpdir=/home/oracle/apache-tomcat-5.5.14/temp
org.apache.catalina.startup.Bootstrap start


Gruss
Ulrik

[Bernd Eckenfels]

Post by Ulrik Hoffmann
- irgendwann läuft die Anwendung gegen die im Connector eingestellten
"maxThreads" und antwortet zunächst schleppender, irgendwann gar nicht mehr

Klingt nach einem Fehler in der Anwendung, weiss aber nicht warum der Timeout nicht zuschlaegt.

Post by Ulrik Hoffmann
Die Anwendungen benutzt JSPs/Servlet und läuft gegen eine Oracle 10GR2
Datenbank. Das Verhalten wurde sowohl unter Tomcat 5.0.28/jdk1.4 und
5.5.14/jdk1.5 beobachtet, sowohl unter Suse 8.2 native und einem
gentoo-Linux unter VMware.

Zieh einfach nen Thread Dump dann solltest du sehen wo die Anwendung klemmt.
Ist vermutlich nen synchronized auf nem Object das per Klassen-Feld
zugegriffen wird.

Post by Ulrik Hoffmann
Das Verhalten ist durch "Trommelfeuer" auf Aktualisieren-Button jederzeit
reproduzierbar.

Gibts wenn das anfangt Fehler (Exceptions), dann fehlt ein final block.

Gruss
Bernd

[Dirk Försterling]

Post by Ulrik Hoffmann
- kommt die Kombination "etwas längere Abfragezeit" und "ungeduldige"
Nutzer zusammen, klicken die Leute (Rheinländer ;-)) mehrfach auf die
Links in der Hoffnung, die Seiten würden schneller ausgeliefert.

Wäre eine "Bitte Warten...."-Seite mit refresh und/oder ein bischen
Session-Management vielleicht erstmal ein Workaround? (Einfach um zu
verhindern, daß die überzähligen Klicks irgendwas bewirken)

Post by Ulrik Hoffmann
- diese Prozesse werden nicht wieder abgebaut und bleiben bestehen

Ich denke auch, wie in den anderen Postings schon fesgestellt wurde,
das dies Threads der JVM sind.

Es könnten Deadlocks oder "einfach" nicht beendete Threads sein.
(Ich gehe jetzt mal davon aus, daß es kein Problem mit Java oder
Tomcat selbst ist)

Post by Ulrik Hoffmann
- Fehlermeldungen werden nicht protokolliert :-(

Dann wird's aber Zeit ;-)

Post by Ulrik Hoffmann
Hat jemand von Euch ne Idee, woran das liegen könnte und kann mir einen
Tipp geben, wonach ich suchen soll?

Nach dem auftretenden verhalten. Was genau passiert denn, wenn die
ungeduldigen die Links mehrfach anklicken? Dabei würde ich vor allem
auf irgendwelche Bedingungen bezüglich geteilter Ressourcen schauen,
die zu Deadlocks führen können.
Falls Threads benutzt werden: Verlassen diese Threads unter den
beschriebenen Bedingungen jemals ihre run()-Methode? Eventuell werden
auch irgendwelche Thread-Objekte erzeugt, aber aus irgendeinem Grund
wird start() nicht aufgerufen?

Vielleicht läßt sich das Problem ja mit einem geeigneten Debugger
nachstellen, um einfach mal nachzusehen an welcher Stelle die Threads
hängen bleiben.

-dirk

[Frank Fischer]

[Tomcat hängt nach Mehrfachrequests...]

Was ergibt der auch schon von anderen empfohlene Threaddump?

Hier ist erkennbar, wo sich die Threads "verklemmen".

Ansonsten: Was spricht dagegen einfach per Javascript den Mehrfachreqest
zu unterbinden?

Es ist sicherlich nicht die perfekte Lösung aber entschäft erstmal die
Probleme.

Das serverseitige Abfangen solcher Mehrfachrequests ist erheblich
aufwändiger.

HTH,

Frank

[Bernd Eckenfels]

Post by Frank Fischer
Das serverseitige Abfangen solcher Mehrfachrequests ist erheblich
aufwändiger.

im gegenteil, statische hashtable mit action id - macht immer sinn, das
hilft auch gegen back buttons und so.

Und ausserdem kann man den Worker Thread an die Session haengen, dann werden
die request threads nicht vollgemuellt.

Gruss
Bernd

[Frank Buss]

Post by Frank Fischer
Was ergibt der auch schon von anderen empfohlene Threaddump?

ich habe so ein ähnliches Problem von Zeit zu Zeit. Wie kann man denn ein
Threaddump in einem laufenden Produktionssystem ziehen?

[Bernd Eckenfels]

Post by Frank Buss
ich habe so ein ähnliches Problem von Zeit zu Zeit. Wie kann man denn ein
Threaddump in einem laufenden Produktionssystem ziehen?

kill -QUIT aber das geht nur wenn du die stdout umgeleitet hast und du kein
-Xrs benutzt. Sonst musste halt nen debugger attachen. (ich weiss auch nicht
-warum sun da kein logfile erlaubt)

Mit JMX sieht man glaube die stacktraces nicht, oder?

Gruss
Bernd

[Frank Buss]

Post by Bernd Eckenfels
kill -QUIT aber das geht nur wenn du die stdout umgeleitet hast und du kein
-Xrs benutzt. Sonst musste halt nen debugger attachen. (ich weiss auch nicht
-warum sun da kein logfile erlaubt)

Das klingt schonmal interessant, klappt aber nur bei einer einzigen PID,
die in der "ps ax"-Liste zu sehen ist. Ich habe es jetzt per "kill -QUIT
`ps ax --width 1000|grep java|sed -e "s/^[^0-9]*\([0-9]*\).*$/\1/"`" an
alle geschickt, aber vielleicht gibt es ja eine Möglichkeit, die passende
direkt zu ermitteltn?

Post by Bernd Eckenfels
Mit JMX sieht man glaube die stacktraces nicht, oder?

Doch, habe ich auch schonmal etwas zu programmiert:
http://tinyurl.com/9beq7
Nur mit dem -QUIT ist ja viel einfacher :-)

[Bernd Eckenfels]

Post by Frank Buss
Das klingt schonmal interessant, klappt aber nur bei einer einzigen PID,

wenn dein ps noch die einzelnen threads anzeigt (ich glaub 2.6 kernel macht
das nimmer mit den neuen ps tools), dann kannst du ps -fax nehmen um den
gemeinsamen parent zufinden. Oder halt jps, welches auf den JIT data files
basiert. Unter Unix sind die in /tmp/hsperfdata_<USER>/<pid>/

Hier mal gekürtzt:

***@seedebrcvs:~$ /opt/jdk1.5.0/bin/jps -l
18643 org.apache.catalina.startup.Bootstrap
12124 sun.tools.jps.Jps
***@seedebrcvs:~$ ls -l /tmp/hsperfdata_*
/tmp/hsperfdata_genie:
-rw------- 1 genie genieadm 32768 Dec 13 12:28 18643
***@seedebrcvs:~$ ps fax | grep java
18643 ? S 244:56 /opt/jdk1.5.0/bin/java ... org...Bootstrap start

Gruss
Bernd

[Frank Buss]

Post by Bernd Eckenfels
wenn dein ps noch die einzelnen threads anzeigt (ich glaub 2.6 kernel macht
das nimmer mit den neuen ps tools), dann kannst du ps -fax nehmen um den
gemeinsamen parent zufinden. Oder halt jps, welches auf den JIT data files
basiert. Unter Unix sind die in /tmp/hsperfdata_<USER>/<pid>/

klappt alles nicht. "ps fax" liefert z.B. das hier:

852 ? S 0:08 /usr/local/java5/bin/java
-Djava.awt.headless=true -X
873 ? S 0:00 \_ /usr/local/java5/bin/java
-Djava.awt.headless=tru
874 ? S 0:04 \_ /usr/local/java5/bin/java
-Djava.awt.headless
875 ? S 0:00 \_ /usr/local/java5/bin/java
-Djava.awt.headless
877 ? S 0:00 \_ /usr/local/java5/bin/java
-Djava.awt.headless
892 ? S 0:00 \_ /usr/local/java5/bin/java
-Djava.awt.headless
893 ? S 0:01 \_ /usr/local/java5/bin/java
-Djava.awt.headless
894 ? S 0:00 \_ /usr/local/java5/bin/java
-Djava.awt.headless
895 ? S 0:00 \_ /usr/local/java5/bin/java
-Djava.awt.headless

und "jps -l" das hier:

1012 sun.tools.jps.Jps
852 org.apache.catalina.startup.Bootstrap

aber ein "kill -QUIT 852" lieferte keine Stackdump-Ausgabe, in diesem Fall
war es beim Prozess 874 erfolgreich. Wenns also immer der erste in der
tiefsten Ebene der "ps fax" Anzeige wäre (und immer an 3. Stelle steht),
dann könnte ich damit aber auch leben und es per "kill -QUIT `ps --width
1000 fax|grep java|grep catalina|head -n3|tail -n1|sed -e
"s/^[^0-9]*\([0-9]*\).*$/\1/"`" automatisieren :-)

[Bernd Eckenfels]

ich glaub mit dem 2.6er kernel in dem die threads nicht als prozesse
gehandhabt werden geht das, weil das signal an alle threads zugesellt wird.

Ich hab kein alten kernel da aber probier mal:

ps -faxo pid,user,pgid,args

prozess group ids kann man als negative pids dem kill mitgeben.

Gruss
Bernd

[Frank Buss]

Post by Bernd Eckenfels
ich glaub mit dem 2.6er kernel in dem die threads nicht als prozesse
gehandhabt werden geht das, weil das signal an alle threads zugesellt wird.
ps -faxo pid,user,pgid,args
prozess group ids kann man als negative pids dem kill mitgeben.

danke, mit der prozess group id funktioniert es. Damit vereinfacht sich der
Ausdruck, um das ohne manuelle Sichtung der Prozessliste zu automatisieren:

kill -QUIT -`ps faxo pgid,args|grep java|grep catalina|head -n1|sed -e
"s/^[^0-9]*\([0-9]*\).*$/\1/"`

[Ulrik Hoffmann]

Hi,

erstmal vielen Dank. Der Tipp mit dem Synchronized wars, eine Klasse war
damit deklariert. Nun verhält es sich so wie erwartet: Threads werden bis
MaxThreads aufgebaut, aber auch wieder abgebaut, das System bleibt
bedienbar.

Der Tipp mit dem Thread-Dump hat auch gut funktioniert --> werd ich mir
merken!

Vielen Dank noch mal!

Gruss
Ulrik

[Frank Buss]

Post by Ulrik Hoffmann
erstmal vielen Dank. Der Tipp mit dem Synchronized wars, eine Klasse war
damit deklariert. Nun verhält es sich so wie erwartet: Threads werden bis
MaxThreads aufgebaut, aber auch wieder abgebaut, das System bleibt
bedienbar.

Da musst du allerdings aufpassen, meist hat sich der Programmierer was
dabei gedacht. Wenn es dann auf einmal nicht mehr synchronisiert ist, kann
es zu interessanten Effekten kommen. Besser ist es, die Ursache eines
Deadlocks zu finden und es synchronisiert zu lassen.

[Ulrik Hoffmann]

Post by Frank Buss
Da musst du allerdings aufpassen, meist hat sich der Programmierer was
dabei gedacht. Wenn es dann auf einmal nicht mehr synchronisiert ist, kann
es zu interessanten Effekten kommen. Besser ist es, die Ursache eines
Deadlocks zu finden und es synchronisiert zu lassen.

Schon klar. Allerdings hat sich _der_ Programmierer wahrscheinlich nichts
dabei gedacht. Ich kann mich erinnern (hatte damals die DB-Seite gemacht),
dass wir das Problem mit den hektischen Klicks schon von Anfang an hatten
und er mit synchronized "experimentiert", um die Leute an
Multiplen-Requests zu hindern. Transaktionsseitig ist das kein Problem,
das synchronized weg zu nehmen.

Gruss
Ulrik