Les métriques peuvent vous tromper : mesurer le temps d'exécution dans des environnements regroupés en pool de connexions

Mesurer le temps d'exécution des requêtes adressées aux services externes est essentiel pour le suivi et l'optimisation des performances. Cependant, lorsque les connexions à ces services externes sont regroupées, vous risquez par inadvertance de mesurer plus que le simple temps de requête. Plus précisément, si les requêtes prennent trop de temps et que vous manquez de connexions disponibles, votre logique personnalisée peut commencer à inclure le temps d'attente pour obtenir une connexion à partir du pool. Cela peut conduire à des mesures trompeuses, vous amenant à mal interpréter les performances de votre système. Voyons comment cela se produit et comment vous pouvez éviter de vous laisser tromper par vos propres mesures.

Le piège : inclure le temps d’attente dans les mesures

Lorsque toutes les connexions du pool sont utilisées, les demandes supplémentaires doivent attendre qu'une connexion soit disponible. Ce temps d'attente peut fausser vos statistiques s'il n'est pas mesuré séparément du temps réel de la demande.

Scénario : manque de connexions

1. État initial : votre pool de connexions dispose d'un nombre fixe de connexions, qui sont toutes utilisées.
2. Nouvelle demande : une nouvelle demande arrive mais doit attendre qu'une connexion soit disponible.
3. Temps d'attente : la demande attend (éventuellement pendant un temps important) jusqu'à ce qu'une connexion soit libre.
4. Durée de la demande : une fois la connexion obtenue, la demande proprement dite est effectuée.

Si votre logique personnalisée mesure le temps total entre le moment où la demande a été faite et la réception d'une réponse, vous incluez à la fois le temps d'attente et le temps de demande.

Exemple pratique : reproduire le problème dans Spring Boot avec Apache HttpClient 5

Pour illustrer comment vous pouvez vous laisser tromper par vos propres métriques dans un environnement de pool de connexions, passons en revue un exemple pratique utilisant Spring Boot et Apache HttpClient 5. Nous allons configurer une simple application Spring Boot qui envoie des requêtes HTTP à un service externe, mesurez le temps d'exécution de ces requêtes et démontrez comment l'épuisement du pool de connexions peut conduire à des métriques trompeuses.

Pour simuler les retards dans le service externe, nous utiliserons l'image httpbin Docker. Httpbin fournit un service de requête et de réponse HTTP facile à utiliser, que nous pouvons utiliser pour créer des retards artificiels dans nos requêtes.

@SpringBootApplication
@RestController
public class Server {

    public static void main(String... args) {
        SpringApplication.run(Server.class, args);
    }

    class TimeClientHttpRequestInterceptor implements ClientHttpRequestInterceptor {

        @Override
        public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution)
                throws IOException {
            var t0 = System.currentTimeMillis();
            try {
                return execution.execute(request, body);
            } finally {
                System.out.println("Request took: " + (System.currentTimeMillis() - t0) + "ms");
            }
        }
    }

    @Bean
    public RestClient restClient() {
        var connectionManager = new PoolingHttpClientConnectionManager();
        connectionManager.setMaxTotal(2); // Max number of connections in the pool
        connectionManager.setDefaultMaxPerRoute(2); // Max number of connections per route

        return RestClient.builder()//
                .requestFactory(new HttpComponentsClientHttpRequestFactory(
                        HttpClients.custom().setConnectionManager(connectionManager).build()))
                .baseUrl("http://localhost:9091")//
                .requestInterceptor(new TimeClientHttpRequestInterceptor()).build();
    }

    @GetMapping("/")
    String hello() {
        return restClient().get().uri("/delay/2").retrieve().body(String.class);
    }
}

Dans le code ci-dessus, nous avons créé un intercepteur de requêtes (ClientHttpRequestInterceptor) pour mesurer ce que nous pensions être le temps d'exécution des requêtes adressées au service externe soutenu par httpbin.

Nous avons également explicitement réglé la piscine sur une très petite taille de 2 connexions pour faciliter la reproduction du problème.

Il ne nous reste plus qu'à démarrer httpbin, exécuter notre application Spring Boot et effectuer un test simple en utilisant ab

$ docker run -p 9091:80 kennethreitz/httpbin

ab -n 10 -c 4 http://localhost:8080/
...
Percentage of the requests served within a certain time (ms)
  50%   4049
  66%   4054
  75%   4055
  80%   4055
  90%   4057
  95%   4057
  98%   4057
  99%   4057
 100%   4057 (longest request)

Request took: 2021ms
Request took: 2016ms
Request took: 2022ms
Request took: 4040ms
Request took: 4047ms
Request took: 4030ms
Request took: 4037ms
Request took: 4043ms
Request took: 4050ms
Request took: 4034ms

Si nous regardons les chiffres, nous pouvons voir que même si nous avons fixé un délai artificiel de 2 secondes pour le serveur externe, nous obtenons en réalité un délai de 4 secondes pour la plupart des requêtes. De plus, on remarque que seules les premières requêtes honorent le délai configuré de 2 secondes, tandis que les requêtes suivantes entraînent un délai de 4 secondes.

Il est temps de créer un profil

Le profilage est essentiel lorsque vous rencontrez un comportement de code étrange, car il identifie les goulots d'étranglement des performances, découvre les problèmes cachés tels que les fuites de mémoire et montre comment votre application utilise les ressources système.

Cette fois, nous profilerons l'application en cours d'exécution à l'aide de JFR tout en effectuant les tests de charge ab.

$ jcmd <pid> JFR.start name=app-profile  duration=60s filename=app-profile-$(date +%FT%H-%M-%S).jfr

$ ab -n 50 -c 4 http://localhost:8080/
...
Percentage of the requests served within a certain time (ms)
  50%   4043
  66%   4051
  75%   4057
  80%   4060
  90%   4066
  95%   4068
  98%   4077
  99%   4077
 100%   4077 (longest request)

Si nous ouvrons le fichier JFR et regardons le flamegraph, nous pouvons voir que la majeure partie du temps d'exécution est passée par notre client HTTP. Le temps d'exécution du client est partagé entre l'attente de la réponse de notre service externe et l'attente d'obtenir une connexion depuis le pool.

Cela explique pourquoi les temps de réponse que nous voyons sont le double du délai fixe attendu de 2 secondes que nous avons défini pour notre serveur externe. Nous avons configuré un pool de 2 connexions. Cependant, lors de notre test, nous effectuons 4 requêtes simultanées. Ainsi, seules les 2 premières requêtes seront servies dans le délai prévu de 2 secondes. Les requêtes ultérieures devront attendre que le pool libère une connexion, augmentant ainsi le temps de réponse observé.

Si nous regardons à nouveau le flamegraph, nous pouvons également découvrir pourquoi le temps mesuré par notre ClientHttpRequestInterceptor ne reflète pas le temps qu'il faut au serveur externe pour répondre mais le temps qu'il faut pour obtenir une connexion depuis le pool plus le temps qu'il faut pour effectuer la requête réelle au serveur externe. Notre intercepteur encapsule en fait une trace de pile qui finit par appeler un gestionnaire de pool pour obtenir une connexion : PoolingHttpClientConnectionManager

Il est préférable de surveiller le temps de réponse de n'importe quel client HTTP à l'aide de ses métriques intégrées, car ces métriques sont spécifiquement conçues pour capturer des informations de synchronisation précises. Ils prennent en compte tous les aspects du cycle de vie des requêtes HTTP, notamment l'acquisition de connexions, la transmission de données et la gestion des réponses. Cela garantit que les mesures sont précises et cohérentes avec les performances réelles du client.

Ce qui précède est le contenu détaillé de. pour plus d'informations, suivez d'autres articles connexes sur le site Web de PHP en chinois!