JBoss threads en attente sur un moniteur aléatoire

Question

Je fais des tests de charge sur une application web déployée dans JBoss. Il démarre bien, mais comme les rampes d'essai vers le haut et les utilisateurs plus simulés commencer à frapper JBoss, les performances se dégradent sévèrement:

Resposne time chart http://i46.tinypic.com/2mob2f9.jpg

Connexion VisualVM à elle, je peux voir les fils étaient bien, puis tout à coup commencé à dépenser la plupart de leur temps d'attente pour un moniteur (vert est en cours d'exécution, le rouge est le moniteur, le jaune est attente):

Thread state graph http://i46.tinypic.com/105v6lk.jpg

Courir jstack, je vois les fils sont tous en attente dans le même endroit:

"http-0.0.0.0-8080-172" daemon prio=6 tid=0x000000005da90000 nid=0xd2c waiting for monitor entry [0x000000006cb4e000] 
    java.lang.Thread.State: BLOCKED (on object monitor) 
    at org.apache.log4j.Category.callAppenders(Category.java:185) 
    - waiting to lock (a org.apache.log4j.spi.RootCategory) 
    at org.apache.log4j.Category.forcedLog(Category.java:372) 
    at org.apache.log4j.Category.debug(Category.java:241) 
    [my code]

La plupart des threads du processeur HTTP ~ 200 attendent le même moniteur. En regardant log4j.xml pour le WAR, il a une configuration d'appender unique pour CONSOLE. Je supprime l'appender et recommence mon test. Même comportement, à l'exception jstack montre tous les fils d'attente dans un endroit différent:

"http-0.0.0.0-8080-251" daemon prio=6 tid=0x0000000059811800 nid=0x1108 waiting for monitor entry [0x0000000073ebe000] 
    java.lang.Thread.State: BLOCKED (on object monitor) 
    at java.util.Hashtable.get(Hashtable.java:333) 
    - waiting to lock (a org.jboss.util.property.PropertyMap) 
    at java.util.Properties.getProperty(Properties.java:932) 
    at org.jboss.util.property.PropertyMap.getProperty(PropertyMap.java:626) 
    at java.lang.System.getProperty(System.java:653) 
    at org.jaxen.saxpath.helpers.XPathReaderFactory.createReader(XPathReaderFactory.java:109) 
    at org.jaxen.BaseXPath.(BaseXPath.java:124) 
    at org.jaxen.BaseXPath.(BaseXPath.java:153) 
    at nu.xom.JaxenConnector.(JaxenConnector.java:49) 
    at nu.xom.Node.query(Node.java:424) 
    [my code]

rien changer, je redémarre JBoss, exécutez le test, puis exécutez jstack une fois qu'il est lent. Tous les fils attendent encore dans un autre lieu:

"http-0.0.0.0-8080-171" daemon prio=6 tid=0x000000005d0d1000 nid=0x15d4 waiting for monitor entry [0x000000006cb4e000] 
    java.lang.Thread.State: BLOCKED (on object monitor) 
    at sun.nio.cs.FastCharsetProvider.charsetForName(FastCharsetProvider.java:118) 
    - waiting to lock (a sun.nio.cs.StandardCharsets) 
    at java.nio.charset.Charset.lookup2(Charset.java:449) 
    at java.nio.charset.Charset.lookup(Charset.java:437) 
    at java.nio.charset.Charset.isSupported(Charset.java:479) 
    at sun.nio.cs.StreamDecoder.forInputStreamReader(StreamDecoder.java:49) 
    at java.io.InputStreamReader.(InputStreamReader.java:57) 
    at java.io.FileReader.(FileReader.java:41) 
    [my code]

Que dans le diable se passe? J'ai utilisé jstack dans le passé et j'ai essayé de l'utiliser quand les choses tournent bien et j'ai obtenu les résultats attendus. Je suppose que jstack va bien. Des idées qui pourraient causer un tel comportement étrange? Des idées sur où aller à partir d'ici?

Answer 1

J'ai configuré l'application dans Tomcat à travers Eclipse et je n'ai pas vu le problème. Finalement, j'ai découvert que nous commencions JBoss en utilisant un wrapper de service Windows 32 bits, même si nous utilisions un JDK 64 bits. La machine était 64 bits. Je ne suis pas sûr comment cela fonctionnerait même? En tout cas, passer à un JDK 32 bits a fait disparaître le problème fou et j'ai pu continuer ma vie.

Answer 2

Ce type de comportement est à prévoir. Au fur et à mesure que vous intensifiez un test de charge, vous allez toujours trouver des goulots d'étranglement, et dans un système complexe, ces goulets d'étranglement vont se déplacer.

Votre travail consiste à identifier ces goulets d'étranglement et à essayer de les résoudre, un à la fois. Chaque fois que vous le faites, vous en trouverez toujours un autre, mais nous espérons que le système évoluera mieux à chaque fois. Ce n'est pas facile, mais la mise à l'échelle pour la charge n'est pas facile.

• Prenez votre premier exemple. Vous avez beaucoup d'appels à la méthode Logger.debug() de log4j. Log4j ne fonctionne pas bien lors de la connexion sous charge, vous devez donc prendre quelques précautions. Même si votre configuration log4j dit "ne pas enregistrer les messages DEBUG", log4j doit encore faire un peu de travail avant de s'en rendre compte. L'approche recommandée pour gérer est d'enrouler tous les appels Logger.debug() dans un if Logger.isDebugEnabled() {Logger.debug(); } `bloc. Cela devrait changer ce goulot d'étranglement particulier.

• Dans votre deuxième exemple, vous appelez la méthode Node.query() de XOM. Cette méthode doit recompiler l'expression XPath à chaque appel, ce qui semble être un goulot d'étranglement. Trouvez une API où vous pouvez pré-compiler l'expression XPath et la réutiliser. Dans le 3ème exemple, vous lisez un File. Ce n'est pas une bonne idée dans un système à forte charge, le fichier-io est lent lorsque vous effectuez un grand nombre de petites opérations. Pensez à ré-implémenter cela pour travailler différemment si vous le pouvez.

Tous ces éléments sont sans rapport, mais tous les goulots d'étranglement actuels de performance que vous verrez lors du redimensionnement de la charge. Vous ne vous débarrasserez jamais de tous, mais j'espère que vous pourrez l'atteindre à un point où cela sera suffisant.