Lors d’une journée de conseil, un client m’a demandé entre autres comment effectuer des tests de performances sur des web services REST. Ces tests de performances pourraient ensuite être intégrés au processus d’intégration continue. Une des préoccupations étaient notamment d’instrumenter facilement les web services et d’avoir des métriques intéressantes (temps de réponse moyen, percentiles, etc). La question a finalement tourné court, puisqu’en moins de 10 minutes de live coding, l’objectif était rempli, grâce à Spring Boot et Metrics Dropwizard. Voyons comment !

Que monitorer ?

La cible serait l’ensemble des contrôleurs REST d’une application Spring Boot. Un exemple de contrôleur :

@RestController
public class ApplicationController {
    @RequestMapping("/entities/{id}")
    public String get(@PathVariable String id) {
        return "Requested entity: "+id;
    }
    @RequestMapping("/entities")
    public List<String> select() {
        return Arrays.asList("one","two","three");
    }
}

L’idée serait de mesurer les performances d’un tel contrôleur sans impacter le code.

Les ingrédients de la réussite

Voici ce qui nous permet d’atteindre notre but en quelques minutes :
– décorer facilement tout ou partie des contrôleurs via un HandlerInterceptor Spring MVC
– utiliser les Metrics Dropwizard, car les métriques natives de Spring Boot ne sont pas aussi sophistiquées
– exposer les métriques via l’endpoint /metrics de Spring Boot

Quelques dépendances à ajouter

L’actuator de Spring Boot propose un ensemble de endpoints intéressants, notamment celui exposant les métriques. Spring Boot détecte aussi automatiquement si Metrics est sur le classpath, il nous suffit donc d’ajouter les dépendances :

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
  <groupId>io.dropwizard.metrics</groupId>
  <artifactId>metrics-core</artifactId>
  <version>3.1.2</version>
</dependency>

L’intercepteur

Spring MVC appelle des HandlerInterceptors enregistrés autour des contrôleurs. On peut donc démarrer un timer avant une méthode de contrôleur et l’arrêter à la fin de l’exécution.
Voici le code de l’intercepteur :

public class MetricsHandlerInterceptor implements HandlerInterceptor {
    @Autowired MetricRegistry registry;
    ThreadLocal<Timer.Context> contexts = new ThreadLocal<>();
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
                                              Object handler) throws Exception {
        Timer.Context context = registry.timer(createMetricId(handler)).time();
        contexts.set(context);
        return true;
    }
    protected String createMetricId(Object handler) {
        HandlerMethod handlerMethod = (HandlerMethod) handler;
        return handlerMethod.getBeanType().getName()+"."
                  +handlerMethod.getMethod().getName();
    }
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response,
                              Object handler, ModelAndView modelAndView) throws Exception {
    }
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response,
                                                 Object handler, Exception ex) throws Exception {
        try {
            contexts.get().stop();
        } finally {
            contexts.remove();
        }
    }
}

Quelques points à noter :
– comme Metrics est sur le classpath, Spring Boot crée automatiquement un bean MetricRegistry, il suffit de l’injecter pour pouvoir l’utiliser.
– une variable ThreadLocal nous permet de stocker le contexte du timer
– l’identifiant du timer est créé à partir du nom de classe et de la méthode appelée, on peut récupérer ces informations grâce à l’abstraction HandlerMethod.
Il faut ensuite enregistrer l’intercepteur :

@Configuration
public static class MetricsConfiguration extends WebMvcConfigurerAdapter {
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(metricsHandlerInterceptor());
    }
    @Bean public HandlerInterceptor metricsHandlerInterceptor() {
        return new MetricsHandlerInterceptor();
    }
}

Les métriques

On peut ensuite lancer l’application et après quelques rafraichissements frénétiques de http://localhost:8080/entities et http://localhost:8080/entities/1, on peut consulter l’endpoint http://localhost:8080/metrics ;

{
  ...
  com.zenika.ApplicationController.select.snapshot.999thPercentile: 101,
  com.zenika.ApplicationController.select.snapshot.95thPercentile: 98,
  com.zenika.ApplicationController.select.snapshot.98thPercentile: 101,
  com.zenika.ApplicationController.select.count: 48,
  com.zenika.ApplicationController.select.fifteenMinuteRate: 5.24559812446707,
  com.zenika.ApplicationController.select.snapshot.mean: 50,
  com.zenika.ApplicationController.select.snapshot.max: 101,
  com.zenika.ApplicationController.select.snapshot.99thPercentile: 101,
  com.zenika.ApplicationController.select.snapshot.median: 53,
  com.zenika.ApplicationController.select.fiveMinuteRate: 4.94999144308631,
  com.zenika.ApplicationController.select.oneMinuteRate: 3.4966474384970243,
  com.zenika.ApplicationController.select.snapshot.min: 0,
  com.zenika.ApplicationController.select.snapshot.stdDev: 29,
  com.zenika.ApplicationController.select.meanRate: 1.2863865991540484,
  com.zenika.ApplicationController.select.snapshot.75thPercentile: 76,
  com.zenika.ApplicationController.get.fiveMinuteRate: 4.725935922831916,
  com.zenika.ApplicationController.get.snapshot.999thPercentile: 103,
  com.zenika.ApplicationController.get.snapshot.mean: 54,
  com.zenika.ApplicationController.get.oneMinuteRate: 2.772452442775998,
  com.zenika.ApplicationController.get.meanRate: 0.5838144470692065,
  com.zenika.ApplicationController.get.snapshot.95thPercentile: 86,
  com.zenika.ApplicationController.get.snapshot.median: 56,
  com.zenika.ApplicationController.get.snapshot.max: 103,
  com.zenika.ApplicationController.get.snapshot.stdDev: 24,
  com.zenika.ApplicationController.get.count: 27,
  com.zenika.ApplicationController.get.fifteenMinuteRate: 5.165255191156357,
  com.zenika.ApplicationController.get.snapshot.min: 12,
  com.zenika.ApplicationController.get.snapshot.75thPercentile: 78,
  com.zenika.ApplicationController.get.snapshot.98thPercentile: 103,
  com.zenika.ApplicationController.get.snapshot.99thPercentile: 103
}

On obtient des métriques très précises et très utiles (merci Metrics !). A noter que j’ai ajouté de la latence aléatoire pour rendre les métriques plus intéressantes.

Conclusion

En quelques lignes de codes, on obtient des métriques sur les temps de réponses de web services REST, sans toucher au code applicatif. On peut facilement activer ou désactiver cet intercepteur via les profils Spring, car il n’est pas forcément destiné à tourner en production. Il peut être par exemple utilisé dans un pipeline de déploiement continu, pour monitorer les performances des web services chargés par un outil comme JMeter. Un mécanisme de vérification peut ensuite facilement valider les performances grâce à l’endpoint /metrics.
Code source