Il y a peu, j’ai découvert le profiler SQL de VisualVM et je me suis dit que je devais aussi vous le faire découvrir ;).

VisualVM est un outil qui fournit une interface visuelle pour afficher des informations détaillées sur les applications qui s’exécutent sur une machine virtuelle Java (JVM). VisualVM est conçu pour une utilisation au développement et en production.

VisualVM fournit des outils de profiling léger dont un profiler SQL. Celui-ci va détecter chaque requête SQL (passant par la couche JDBC) et les regrouper dans une vue tabulaire avec le nombre d’exécutions de la requête et le temps total d’exécution.

Cette vue tabulaire permet en un coup d’œil de détecter les requêtes qui impactent le plus la performance. En effet, une requête appelée souvent mais répondant rapidement n’est généralement pas problématique, de même une requête ayant un important temps d’exécution, mais s’effectuant rarement n’est généralement pas problématique pour la performance globale d’une application (mais peut l’être pour la partie de l’application qui la génère). Quand on veut optimiser les performances d’une application, on va donc généralement s’intéresser aux requêtes dont le temps d’execution totale (l’addition des temps de chaque exécution de la requête) est la plus importante. Généralement, on va regarder le top 3, 5 ou 10 des requêtes ayant le plus haut temps d’exécution totale et chercher à les optimiser.

Voici un exemple d’optimisation faite suite à analyse des performances de Kestra en utilisant le profiler SQL de VisualVM. Kestra est une plate-forme d’orchestration et de scheduling de donnée hautement scalabe, qui crée, exécute, planifie, et surveille des millions de pipelines complexes. C’est aussi la société dans laquelle je travaille depuis 3 mois !

Kestra, en version open source, utilise un moteur base de données, l’Edition d’Entreprise permet d’utiliser un moteur alternatif basée sur Kafka et Elasticsearch. Le moteur base de données supporte H2, PostgreSQL, et MySQL. L’optimisation en question a été réalisé pour PostgreSQL.

Le profiler JDBC de VisualVM est accessible via l’onglet Profiler en cliquant sur le bouton JDBC. On peut le configurer avec un texte pour filtrer les requêtes à analyser. Une fois lancé, celui-ci va enregistrer chaque requête exécutée et afficher un tableau avec, pour chaque requête, le temps total d’exécution, le pourcentage par rapport à l’ensemble des requêtes, ainsi que le nombre d’exécutions.

Pour mon cas d’utilisation, le résultat était le suivant.

Comme toujours en performance, il faut s’intéresser aux n top problèmes. Ici, je vais m’intérésser aux 4 premières requêtes, qui sont la variation de la même requête sur la table queues. On peut constater qu’unitairement les requêtes prennent environ 7ms; en fonction de la taille de la base de données, elles peuvent prendre beaucoup plus de temps d’exécution. Ici, je suis parti d’une base vierge, un select devrait donc être quasiment immédiat. Même si ce ne sont pas les requêtes les plus longues, comme elles sont exécutées un grand nombre de fois, ce sont elles qui participent le plus au temps d’exécution global sur la base de données (environ 72% ici).

Kestra a une implémentation asynchrone basée sur des queues de messages pour la communication entre ses composants internes, entre autre, lors de l’exécution des flows. Quand le moteur base de données est utilisé, ces queues vont faire des polls sur la table queues de la base de données : toutes les 25ms une requête sera exécutée pour lire les messages à traiter.

Les quatre premières requêtes en terme d’exécution totale sont les requêtes de poll, elles impactent donc directement le temps d’exécution des flow.

Il est possible de voir la requêtes dans sa totalité en faisant un clic droit sur une ligne puis View SQL.

Voici la requête en question :

select "value", "offset" from queues 
where ((type = CAST('io.kestra.core.models.executions.Execution' AS queue_type)) and "consumer_scheduler" = false) 
order by "offset" asc 
fetch next 100 rows only 
for update skip locked

Un explain plan de cette requête montre que, malgré la présence d’un indexe sur la colonne queue_type, l’optimizer de PostgreSQL décide de faire un scan de l’indexe de la primary key ce qui est suboptimal car il va scanner l’intégralité des enregistrements de cet indexe.

PosgreSQL n’ayant pas de hint, il est difficile de le forcer à utiliser un indexe précis. J’ai donc utilisé un petit workaround : j’ai supprimé la primary key et l’ai replacé par un indexe de hash (pour pouvoir accéder rapidement à un message lors de sa suppression). PostgreSQL privilégie alors l’indexe existant sur la colonne queue_type, et le temps d’exécution de la requête s’en trouve grandement amélioré à 1ms environ.

Si on regarde les top requêtes, on voit que dorénavant nos 4 requêtes ne totalisent plus que 23% du temps total d’exécution.

Et le résultat est là ! Presque 50% d’optimisation du temps d’exécution d’un flow en changeant un indexe. Pour plus d’information voir la PR #1012 !