Exception synchronisée

Symptômes

Lors d’un test de performance sur une application J2EE, je note que celle-ci a des soucis de montée en charge. Généralement une ou deux thread dumps peuvent mettre en évidence les points de contentions. Dans mon cas, rien de probant. Je repense alors à l’article publié sur notre blog Chroniques de la performance : À propos de contentions…. Je récupère les sources de l’agent et l’installe sur le serveur d’application, Weblogic 8.1 – JVM 1.4.2. Lancement du tir….

Dès le début de phase plateau, l’agent affiche régulièrement une partie du code que je n’aurais pas soupçonné: la bibliothèque iBatis qui gère l’accès aux données.

[JTPROF] Contention report [id=-1250505672,thread=ExecuteThread: '14' for queue: 'weblogic.kernel.Default',blocked=210ms]
[JTPROF] Stack trace:
[JTPROF]         com.ibatis.sqlmap.engine.accessplan.EnhancedPropertyAccessPlan. (EnhancedPropertyAccessPlan.java:29)
[JTPROF]         com.ibatis.sqlmap.engine.accessplan.AccessPlanFactory.getAccessPlan (AccessPlanFactory.java:62)
[JTPROF]         com.ibatis.sqlmap.engine.exchange.JavaBeanDataExchange.initialize (JavaBeanDataExchange.java:63)
[JTPROF]         com.ibatis.sqlmap.engine.mapping.parameter.BasicParameterMap.setParameterMappingList (BasicParameterMap.java:93)
[JTPROF]         com.ibatis.sqlmap.engine.builder.xml.SqlStatementParser.applyInlineParameterMap (SqlStatementParser.java:431)
[JTPROF]         com.ibatis.sqlmap.engine.builder.xml.SqlStatementParser.processSqlStatement (SqlStatementParser.java:215)
[JTPROF]         com.ibatis.sqlmap.engine.builder.xml.SqlStatementParser.parseGeneralStatement (SqlStatementParser.java:120)

Les temps de blocage affichés vont de 20ms à 500ms !

Analyse

A la lecture de cette pile d’appel, je me dis « encore un bloc synchronisé mal placé dans iBatis« . L’avantage avec l’open source, comme son nom l’indique, est que l’on a accès aux sources. J’ai donc ouvert la classe EnhancedPropertyAccessPlan qui, à ma grande déception, infirma ma 1ère intuition :

27  EnhancedPropertyAccessPlan(Class clazz, String[] propertyNames) {
28    super(clazz, propertyNames);
29    bulkBean = BulkBean.create(clazz, getGetterNames(propertyNames), getSetterNames(propertyNames), getTypes(propertyNames));
30  }

La ligne #29 indique l’appel à une méthode statique de la classe « BulkBean » qui appartient à la bibliothèque cgLib, bien connue pour accélérer efficacement la création de beans Proxy . Idem: cette méthode n’est pas ‘synchronized’. Alors pourquoi l’agent m’indique cette méthode ?
Les grands moyens : injection de traces manuelles dans le code d’iBatis afin de comprendre ce qu’il se trame. Après de nombreux allers-retours de type ‘essais-erreurs’, je finis par trouver l’origine du problème : chaque appel à la méthode BulkBean.create() engendre une levée d’exception NoClassDefFoundError.
En effet, le packaging de l’ear est incomplet : cglib.jar est bien présente mais il manque l’une de ses dépendances : asm. Or le code de la méthode BulkBean.create() s’appuie essentiellement sur l’API d’asm.
Cependant le packaging n’est pas le seul coupable, iBatis est également fautive ! La méthode AccessPlanFactory.getAccessPlan est extrêmement défensive : l’appel à EnhancedPropertyAccessPlan est gardé par un bloc try…catch(Throwable). L’ajout d’un message de log de type « Erreur » aurait été le bienvenue, au moins la première fois.

60:       if (bytecodeEnhancementEnabled) {
61:        try {
62:          plan = new EnhancedPropertyAccessPlan(clazz, propertyNames);
63:        } catch (Throwable t) {
64:          try {
65:            plan = new PropertyAccessPlan(clazz, propertyNames);
66:         } catch (Throwable t2) {
67:            plan = new ComplexAccessPlan(clazz, propertyNames);
68:          }
69:        }

Explications

La levée d’une exception dans une méthode oblige la JVM à rendre l’appel synchronisé afin de garantir un traitement par le catch cohérent. Il ne faudrait pas que les données (attributs, paramètres, variables) aient été modifiées par un autre thread entre la levée de l’exception et son éventuel traitement.

Pour se convaincre de ce phénomène, il suffit d’écrire une simple classe de test : 10 threads, chaque thread appelle une méthode qui suivant un paramètre lève une Exception, une Error ou ne fait rien, et ceci 1 000 000 de fois. Le résultat :

• lorsque la méthode ne lève aucune Exception ou Erreur : Temps de réponse : 89 ms
• lorsque la méthode lève une exception : Temps de réponse 5892 ms, 66 fois plus lent !

Règle: La levée d’exception doit rester un cas exceptionnel et ne dois en aucun cas devenir un design pattern, c’est même un anti-pattern.

public class AntiPattern {
	class NotEvenException extends Exception {
	}

	boolean isEven(int nb) {
		try {
			if (nb % 2 > 0)
				throw new NotEvenException();
			return true;
		} catch (NotEvenException e) {
			return false;
		}
	}
}

Note : Une fois le packaging complet, l’agent jtprof ne mentionne plus du tout cette zone de l’application.