Greg's Devblog Par un développeur, pour les développeurs

Java : lenteurs inexpliquées ?

On aurait du utiliser un profiler. Voilà la conclusion à laquelle je suis arrivé après qu'on ait cherché à améliorer la vitesse et la réactivité de notre application au boulot (pour des appareils à encre électronique, donc en gros le même hardware que sur des smartphones).

Date.toString()

Sur certains écran, l'affichage prenait 6 secondes, alors que sur des écrans équivalents on était largement en-dessous de la seconde. On n'avait pas de profiler disponible sur l'appareil, donc on a commencé à mettre des logs un peu partout pour afficher les différents temps, et là, surprise : ce qui prenait autant de temps, c'est l'affichage des dates ! Un simple date.toString() peut ainsi prendre  plus d'1 seconde, parce que par défaut ça va aller charger tout et n'importe quoi pour trouver les locales et créer de quoi formatter la date comme il faut ! La solution, qui était déjà utilisée, a été de cacher les DateFormatter histoire qu'on ne se prenne pas le surcout à chaque fois et de bien convertir les dates en String en utilisant ce qui est en cache.

Requêtes à 2 à l'heure...

C'était déjà mieux, pas encore parfait. On avait encore des lenteurs assez bizarres sur des requêtes pourtant simples : de bêtes SELECT, UPDATE, ou INSERT pouvaient prendre 1 à 3 secondes, alors que d'autres prenaient à peine quelques millisecondes...

On a donc mis des logs autour de toutes les requêtes, en séparant les moindre lignes, pour essayer d'évaluer au mieux là où on passe trop de temps. Et surprise, l'exécution des requêtes est rapide, le problème n'est pas là ! En fait si on a une méthode qui ne fait que la requête, la ligne qui exécute la requête dans la méthode est rapide, alors que l'appel de la méthode en entier est long... Pas super logique :p

Bon bah c'est simple, il faut virer tout ce qui ne concerne pas directement la requête, à savoir juste des logger.trace qui ne sont même pas affichés, puisqu'on avait mis le mode de log à "info". Et là, gain de vitesse monstrueux !

Et oui, car afin d'avoir un maximum d'informations de debug, on a des logger.trace un peu partout dans le code des requêtes, qui permettent d'afficher toutes les valeurs injectées dans la base ou récupérée depuis celle-ci. Alors certes, rien n'est affiché, mais les arguments passés aux méthodes sont tout de même évalués, et parmi ceux-si on trouve... des dates ! Le retour du foireux Date.toString()...

On a été assez étonné car au final depuis le début on était persuadé d'avoir un problème de lenteur avec la base, alors que le problème était tout autre (et dans le fond venait de nous, et non de SQLite ^^). Ca explique pourquoi on ne trouvait pas trop de monde avec le même souci sur le net.

Régler le problème des logs

J'ai trouvé ce problème un peu con, en fait. C'est un souci qu'on n'aurait pas eu en C/C++ : les méthodes de log sont des macros, et quand on ne veut pas de log, la macro ne défini plus rien, et le log n'est tout simplement plus présent dans le code compilé.

Bon, à part commenter tous les logs (un peu chiant), que peut-on faire en Java pour ne pas avoir ce souci ? On n'a actuellement pas de préprocesseur, mais peut-être faudrait-il envisager d'en mettre un petit, au moins pour les logs... L'autre solution peut être de passer à un autre logger dont un collègue m'a parlé : au lieu de prendre juste un String, il reprend en fait la syntaxe du printf avec les "Date : %s..." et l'utilisation de la date comme argument. Et là, pour le coup, si le logger n'affiche rien, les arguments sont passés mais il n'y a virtuellement rien à évaluer (les dates resteront des Object tant que le logger ne les affiche pas), aucune concaténation de String à faire, c'est beaucoup plus rapide.

Alors certes, c'est mieux, mais conceptuellement ça reste du code qui pourrait être présent dans l'exécutable final, qui ne ferait rien, et qui ne serait pourtant pas 100% gratuit. Et j'ai un peu du mal à me dire que l'exécutable finale pourrait être légèrement (à peine, mais bon) plus lent que ce qu'il pourrait être juste parce qu'on a laissé trainé des debugs dedans...

Si vous avez des solutions alternatives, je suis preneur !

Moral ?

Ce qu'on a eu là comme souci illustre aussi quelques règles de programmation qu'on a parfois tendance à négliger :

1. Pas d'optimisation à l'aveugle : quand on cherche à optimiser, il est important d'avoir des benchs pour savoir si l'optimisation est mieux ou pas que le code d'origine, et surtout savoir si on en train d'optimiser une partie pertinente du code. J'ai ainsi fait des optimisations sur le code d'affichage qui ont eu finalement un impact minime sur les performances globales, puisque 90% de la perte de temps était ailleurs. Et c'est comme ça qu'une fois sur PocketPC j'ai passé quelques heures à faire un code d'affichage beaucoup plus optimal pour me rendre compte que je n'avais rien gagné : GCC faisait aussi bien sur le code d'origine...
2. Se remettre en question avant de douter des autres : ça fait plusieurs mois qu'on sait que les accès à la base sont lents, et depuis le début on a rejeté le faute sur SQLite... Pourtant les bonnes pratiques veulent qu'on vérifie que son propre code n'est pas la cause des lenteurs/bugs avant de dire que c'est dans une librairie qu'on utilise.