Performance, les Xebians jouent les démineurs 3

3ème épisode de notre série. Il est temps pour notre magnifique application de dépasser la barre symbolique de l’utilisateur unique. Mais comme nous nous sentons confiants et forts, nous allons pousser le vice de passer à, tenez vous bien, 5 utilisateurs concurrents. Et comme certains diraient, « Et là, c’est le drame ». Les temps se dégradent à vitesse grand V.

Pour rappel, nous avions laissé notre utilisateur unique avec un temps mirobolant de 1,7 secondes par requête en moyenne.

Le tableau ci dessous montre que la concurrence est nuisible à nos temps de réponse.

La base une ressource critique.

Première amélioration, quasiment gratuite. En allant chercher dans les problèmes que nous avions mis de coté (il y a quelques semaines sur le blog, mais quelques minutes auparavant lors du Xke ;), nous pouvons exhumer le traçage de la totalité des requêtes SQL dans les fichiers de log. Cette fonctionnalité est bien connue des utilisateurs d’Hibernate (très pratique pour débugger), mais elle se retrouve malheureusement bien trop souvent en production.

false

Il suffit alors d’une simple modification dans la configuration d’Hibernate, d’un redéploiement, et miracle, les temps s’améliorent déjà un peu.

• hibernate.show_sql à false
• Temps moyen de 8,2 s à 7,6 s pour 5 utilisateurs
• 1 point pour l’équipe qui a trouvé

Après cette correction facile, attaquons nous à plus complexe.

Si la montée en charge induit une augmentation du temps de réponse, c’est que les utilisateurs sont en concurrence sur un certain type de ressource, ou bien qu’ils mettent la machine à genoux. Un rapide coup d’oeil dans VisualVm nous montre que la CPU et la mémoire ne sont pas saturées, on a donc à faire à une contention applicative.

Celles ci peuvent être de deux types :

• une concurrence applicative, mal gérée avec les outils fournis par java.concurrent.util
• une contention sur des ressources externes, comme un pool de connexions JDBC dans une DataSource.

Comme nous étions déjà sur Hibernate dans la correction précédente, continuons à creuser le sillon. Et profitons en pour dégainer un nouvel outil de notre couteau suisse de diagnostic : JMX.
Pour vérifier si nos connexions JDBC sont bloquantes, utilisons l’api de monitoring de Java. Une fois de plus, utilisons notre VisualVm, qui propose une interface graphique d’affichage des MBeans.
Nous sommes chanceux, nos GO ont utilisé la dataSource standard de Tomcat, elle est donc exposée Catalina:type=DataSource,class=javax.sql.DataSource,name="jdbc/petclinicMySQL"

En procédant par sondage rapide (à l’aide de la fonction ‘refresh’ du MBean), on constate rapidement que les valeurs maxActive et numActive se rejoignent autour de la valeur 3. Pas la peine d’en dire beaucoup plus… Comme d’habitude, la documentation va nous confirmer ce que nous pouvions supposer à la lecture de ces valeurs. maxActive nous donne le nombre maximal de connexion JDBC, alors que numActive nous donne celles qui sont utilisées à l’instant t. Ce qui signifie que lorsque les 3 connexions sont prises, les process suivant se mettent en attente, pendant un temps fixé par maxWait soit 3 secondes. Le goulet d’étranglement est évident. Il suffit donc de le fluidifier.

Ce paramétrage se trouve dans la configuration du serveur tomcat, dans le fichier server.xml. Nous allons agir sur deux paramètres : le maxActive, que nous allons positionner à 30 connexions (ce qui est plus que raisonnable) et sur le maxWait afin de ne pas attendre en vain une connexion qui ne viendra jamais.

Les résultats sont immédiats et nous passons à un temps moyens de 7,2 s :

• Paramétrage de la datasource
• Temps moyen de 7,6 s à 7,2 s pour 5 utilisateurs
• 2 points pour l’équipe qui a trouvé

Ca coince toujours. Où le temps est il consommé ?

Pas la peine d’envisager de passer à plus d’utilisateurs tant que le temps moyen de requête est aussi catastrophique. Si l’on s’intéresse plus en détail aux résultats de JMeter, on constate que la requête Owner detail est la plus consommatrice. Sûrement quelque chose à optimiser de ce côté là.
On ne va pas déroger aux bonnes habitudes prises, on retourne dans VisualVm. Et quand quelque chose coince au niveau applicatif, on réalise un ensemble de ThreadDump. Comme nous sommes avides de nouveauté, nous allons laisser les commandes Unix vi et grep aux dinosaures et utiliser les possibilités de VisualVm, à savoir le plugin Tda.

Pour mettre en évidence notre problème, nous allons tout d’abord restreindre les scenarii JMeter à la seule et unique requête Owner Details. Ensuite, nous allons réaliser une série de ThreadDump très rapproché (de 5 à 10 en quelques secondes). Nous allons ensuite utiliser une des possibilités de TDA, à savoir la détection des Thread longue durée Long Running Thread. TDA va tenter d’identifier les threads ‘bloqués’ dans la même méthode au travers de n ThreadDump.
Comme auparavant, nous ne nous occuperons que des catalina-exec-xx RUNNABLE. Et nous avons de la chance, puisque sur nos cinq utilisateurs, nous trouvons 2 threads bloqués au même point, dans la même méthode (vous l’aurez compris, la détection de thread longue durée est principalement basée sur un ‘coup de sonde’ statistique).

Un petit tour dans le code, dans la classe incriminée.

/**
      Custom handler for rendering images.
      
      @param petId
                 the ID of the pet whose visits to display
      @param response to output the image bytes
      @throws IOException
     */
    @RequestMapping(value = "/owners/*/pets/{petId}/image", method = RequestMethod.GET)
    public void petImageHandler(@PathVariable int petId, HttpServletResponse response) throws IOException {
        int imgId = petId % 6;
        InputStream in = Thread.currentThread().getContextClassLoader().getResourceAsStream("img/pet-" + imgId + ".jpg");
        response.setContentType("image/jpeg");
        OutputStream out = response.getOutputStream();
        IoUtils.copy(in, out);
        clean();
    }

A priori, rien de très suspect dans la façon de servir des images stockées côté serveur (le but de l’exercice n’étant pas d’éliminer le problème, en changeant le comportement de l’application et en déplaçant ces images côté apache).
Si on revient à nos ThreadDump, nous constatons que nous pouvons encore descendre dans le code, à l’intérieur de la classe IoUtils.

    public static void copy(InputStream in, OutputStream out) throws IOException {

        OutputStream bufferedOutputStream = new BufferedOutputStream(out);
        byte[] buffer = new byte[512];
        int length;
        while ((length = in.read(buffer)) >= 0) {
            bufferedOutputStream.write(buffer, 0, length);
        }
        bufferedOutputStream.close();
    }

A priori, si les copies d’InputStream / Outputstream étaient à ce point sous performantes, cela se saurait. Mais ne mésestimons pas la fourberie de nos poseurs de bombes.

En y regardant de plus près, on constate en effet que nous avons une belle implémentation maison de la méthode write, inspirée de celle du ByteArrayOutputstream.

public synchronized void write(int b) {
            int newcount = count + 1;
            if (newcount > buf.length) {
                buf = Arrays.copyOf(buf, (buf.length << 1) / 2 + 3);
            }
            buf[count] = (byte) b;
            count = newcount;
        }

Et là où le ByteArrayOutputstream se redimensionne de manière intelligente pour accélérer la copie

    public synchronized void write(int b) {
  int newcount = count + 1;
  if (newcount > buf.length) {
            buf = Arrays.copyOf(buf, Math.max(buf.length << 1, newcount));
  }
  buf[count] = (byte)b;
  count = newcount;
    }

, l'implémentation maison reste définitivement bloquée et recopie les octets 2 à 2...

Si nous remplaçons cette implémentation par java.io.BufferedOutputstream, nous devrions avoir de bien meilleurs résultats.

Et en effet cette fois, c'est spectaculaire. Pour nos cinq utilisateurs, nous passons à un temps moyen de 1,4 s avec une très remarquée dégringolade du temps moyen de ownersDetail qui passe de 32 s à 3,7 s.

• Suppression d'un java.io maison
• Temps moyen de 7,2 s à 1,4 s pour 5 utilisateurs
• 3 points pour l'équipe qui a trouvé

Il va bientôt être temps de passer à un nombre d'utilisateurs "raisonnable".