Profiling SQL

11 Mar 2011

C’est une étape souvent négligée par les projets utilisant des librairies de mapping objet. Mais faire de l’Hibernate c’est bien, regarder les requêtes générées sur la base c’est mieux.

J’ai le souvenir d’un vieux projet utilisant des EJB Entity 2 où à un moment on ajoutait un objet dans une liste. En regardant les requêtes on s’est aperçu que le conteneur chargeait toute la liste avant de faire l’insert. C’était complètement inutile.

Donc comment étudier correctement les requêtes ? Déjà si vous utilisez hibernate mettez la property “show_sql” à true de temps en temps. Après pour avoir plus d’informations j’utilise p6spy et IronEye SQL.

p6Spy est une librairie qui remplace votre driver de base de données. C’est en quelque sorte un driver proxy de BDD. IronEye apporte juste une vue graphique des informations récoltées par p6spy. Pour trouver de la doc c’est un peu dur p6spy{.link-external} ne fonctionne plus mais j’ai trouvé un site expliquant la mise en place de p6spy et de IronSql.

Par contre ce sont deux outils un peu “vieux”. p6spy n’a pas été mis à jour depuis 2003 et pour IronEye SQL la société IronGrid a disparu. Comme il est maintenant impossible de trouver IronEye en téléchargement je vous propose la version 1.2.359 que j’avais heureusement conservée : ironeyesql-installer-1_2_359.jar. (fonctionne que sur Windows chez moi). Le site sourceForge de p6spy est toujours up.

Sans refaire la doc, installer p6spy c’est simple, il faut juste remplacer le nom de votre driver jdbc par com.p6spy.engine.spy.P6SpyDriver et de mettre le nom du vrai driver dans le fichier spy.properties : realdriver = oracle.jdbc.driver.OracleDriver. Pour utiliser IronEye il faut en plus activer un port d’écoute dans le spy.properties :
module.monitor=com.irongrid.monitor.server.MonitorFactory
monitorport=2000

Et voilà ! vous pouvez observer toutes les requêtes faites sur votre base. IronSQL va les regrouper, les compter et calculer le temps moyen d’exécution.

Sans être DBA vous allez très vite voir quelles requêtes sont faites souvent et les plus longues à s’exécuter. Très pratique pour voir si un cache L2 fonctionne bien ou si on a oublié un index sur une table.

Un exemple concret que j’ai corrigé hier :

Dans un service REST on passe en paramètre l’id d’un objet. C’est un service de monitoring appelé par du matériel pour lui passer des infos et s’assurer qu’il est encore en vie (du polling à défaut de push en gros)

Truc t = trucDao.getById(tid);
t.setLastAccess(now);

Assez logique en java avec hibernate, mais l’objet t n’est jamais utilisé après. Le problème c’est qu’au niveau SQL on a un SELECT qui récupère toutes les informations de l’objet pour ensuite faire un UPDATE. Si en plus vous avez configuré des associations de votre objet en lazzy, ça peut être vraiment problématique.

J’ai changé ce code par :

trucDao.updateDateById(tid, now);

Maintenant il ne reste que la requête UPDATE. Lorsque l’on sait que nous allons avoir plusieurs milliers de “Truc” et qu’ils font cette requète toutes les 15 secondes. Je vous laisse calculer le gain en perf. Dans la même fonction j’ai aussi trouvé une requête SQL faite uniquement pour un log debug : no comment.