Trifft man bei der Entwicklung einer Anwendung auf Performanceprobleme, reicht es meist aus, die verantwortlichen Codebereiche aufzuspüren, um dann den Fehler/das Problem zu beheben. Jedoch gestaltet sich das Auffinden der betroffenen Codestellen meist als schwierig oder langwierig. In jede verdächtige Methode Log-Ausgaben mit der Zeitmessung zu schreiben, wäre unsauber. Mit Spring ist die einfachste Lösung, einen Interceptor zu konfigurieren, der die Methodenaufrufe unterbricht und die Zeitmessung ins Log schreibt.
Als erstes definieren wir einen Advice (Interceptor-Bean), die Implementierung bringt Spring schon mit.
<bean id="timingLogger"
class="org.springframework.aop.interceptor.PerformanceMonitorInterceptor" /> |
Als zweiten Schritt können wir mit der AOP Konfiguration festlegen, welche Methodenaufrufe protokolliert werden sollen, damit die Log-Datei übersichtlich bleibt. Folgend zum Beispiel alle public-Methoden der Spring-Beans im Paket service und allen Unterpaketen:
<aop:config>
<aop:pointcut id="services" expression="execution(* de.myApp.service..*.*(..))" />
<aop:advisor advice-ref="timingLogger" pointcut-ref="services" />
</aop:config> |
Für das Definieren der korrekten pointcut-expression hilft die ausführliche Spring Dokumentation (7.2.3 Declaring a pointcut, Version 3).
Damit das Ergebnis in den Logs auftaucht, sollte für diesen Interceptor der Log-Level auf TRACE stehen:
log4j.logger.org.springframework.aop.interceptor.PerformanceMonitorInterceptor=TRACE |
Die Ausgabe sieht dann zum Beispiel so aus:
2010-06-24 09:06:53,109 TRACE PerformanceMonitorInterceptor:64 - StopWatch 'de.myApp.service.MyService.methodName': running time (millis) = 1813 |
Für eine erste Analyse ist diesen Vorgehen hilfreich, will man jedoch aggregierte Werte über einen Zeitraum bekommen, bietet sich zum Beispiel Perf4J an. Mit diesem Tool lassen sich aggregierte Messwerte (Min, Max, Durchschnitt, Anzahl) in eine extra Logdatei schreiben.
Es besteht aber auch die Möglichkeit einer einfachen eigenen Implementierung:
public class TimingLoggingInterceptor implements MethodInterceptor {
public Object invoke(MethodInvocation invocation) throws Throwable {
StopWatch sw = new StopWatch();
sw.start();
Object returnValue = invocation.proceed();
sw.stop();
System.out.println(
invocation.getClass().getSimpleName() + "#" +
invocation.getMethod().getName() + ": " +
sw.getTotalTimeMillis());
return returnValue;
}
} |
Nun muss nur noch der Wert der Spring-StopWatch gespeichert werden. Diese eigene Lösung ist besonders interessant, wenn nur unter bestimmten Bedingungen die Werte geloggt werden sollen, zum Beispiel wenn die Laufzeit eine definierte Obergrenze überschreitet.
Jan Kuenstler
