Contrairement aux idées reçues, une fois lancée, une application Java se comporte aussi bien qu'une autre en python, dotNet ou autre langage managé. Le gros problème n'est donc pas plus la rapidité de la VM que le temps nécessaire à sa mise en route. Sur une bonne machine, un outil comme Google Closure Compiler prend ainsi 3 secondes à chaque instance, et ce n'est clairement pas le temps qu'il faut pour compiler 100 lignes de JS ;-)

Heureusement il existe une solution rapide à mettre en oeuvre et très efficace : NailGun.

Les lenteurs du démarrage

Java est lent au lancement, c'est un fait tenace que les versions successives de la JVM ne font qu'atténuer. Et je suis bien en peine de le reconnaître mais la CLR (.net), sur ce point, a toujours été diablement plus efficace.

Les raisons de cette lenteur serait un peu longues à énumérer. Disons pour simplifier que coller des classes signées dans des fichiers zip implique, au démarrage de la VM, un ouverture, décompression, passage en revue de toutes les classes de tous les jars qui sont dans le CLASSPATH. Au regard de la taille du JDK, ce n'est finalement pas si lent que cela ;-)

D'un autre côté ce problème n'en est pas réellement un dans le cadre d'usage standard de Java : pour des services lancés sur du long terme. En revanche, s'agissant d'une commande simple, c'est une tout autre histoire.

Une bonne manière serait donc de ne pas avoir à effectuer ce travail à chaque lancement d'une commande. Et c'est exactement ce que réalise NailGun (littéralement "pistolet à clou") depuis prés de... pfff... Huit ans :)

Un serveur JVM

NailGun se compose d'une partie "serveur", écrite en Java, et un client en C. Le principe est finalement simple, le serveur étant écrit en Java induit à son lancement le chargement d'une instance de la JVM et bootstraping du JDK.

Le client n'a plus qu'à lui expédier, via TCP/IP, des noms de classes à exécuter. Le serveur lui renverra en retour les écritures faites par la classe dans sa sortie standard. Et le tour est joué.

Installation

Sur Debian c'est assez simple à installer. Un sudo apt-get install nailgun suffit . En revanche cela ne marchera pas car les mainteneurs ont eu la mauvaise idée de renommer le client ng-nailgun au lieu de ng. Et croyez moi, il n'aime pas cela du tout. Fort heureusement, la correction est assez simple :

gastonsudo ln -s /usr/bin/ng-nailgun /usr/bin/ng

Lancement du serveur

Pas de chichi ni de script d'init pour NailGun (même si c'est assez simple à réaliser). Un simple lancement à la mano en tâche de fond ferra l'affaire. La seule chose à bien faire avant est de définir un CLASSPATH comprenant le JAR de NailGun et celui des applications qui souhaitent en bénéficier. Ici il s'agit du compilateur Closure qui se trouve dans le dossier $PWD/libs

gastonexport CLASSPATH=$PWD/libs/compiler.jar:/usr/share/java/nailgun.jar
gastonjava com.martiansoftware.nailgun.NGServer &
NGServer started on all interfaces, port 2113

Voilà, ça roule, le serveur est en activité sur le port 2113.

Test du client

Pour voir un peu ce que cela donne, voyons une compilation Closure sans NailGun

gastontime java -jar libs/compiler.jar --js sources/server/server.js --js_output_file bin/server/server.js
5,00s user 0,08s system 216% cpu 2,341 total

Ok, donc 2.3 secondes pour 100 lignes de code. Voyons maintenant avec NailGun

gastontime ng com.google.javascript.jscomp.CommandLineRunner --js sources/server/server.js  --js_output_file bin/server/server.js
0,00s user 0,00s system 0% cpu 0,185 total

Et hop, on tombe à 185ms, ce qui change un peu tout vous en conviendrez.

Conclusion

Lorsque j'avais écris la première version de cet article, il y a tout juste 7 ans (!!!) je concluais par "Nailgun est une rustine pratique mais je l'espère bientôt obsolète. Le temps de chargement de Java doit pouvoir être encore à améliorer, ne serait-ce qu'en débridant le vérifieur de classes qui consomme beaucoup de ressources au démarrage."

En bien 7 ans plus tard j'en suis pour mes frais et NailGun, lui, est toujours d'actualité...

Vouloir logger les temps de rendu ou encore le volume de données transmis par requête pour une application nodejs/expressjs peut se révéler compliqué si l'on ne sait pas par quel bout prendre la chaîne des middlewares. L'idée ici est de vous proposer une méthode simple pour tout type de calcul dépendant d'un état pré-requête et post-requête.

Le besoin

Apache dispose de logs bien utiles qui permettent, entre autre, de connaître le status de réponse d'une requête ou encore le volume des données envoyées vers le client, voir, plus récemment, le temps en millisecondes du rendu d'une page.

Avec nodejs/expressjs cette fonctionnalité n'existe pas en standard. Il faut pour l'implémenter utiliser une petite astuce. Ce n'est pas bien sorcier, je vous rassure.

Middleware de base

Dans la mesure où cet article parle d'expressjs, et que vous êtes en train de le lire, je présume que vous êtes habitué au principe de middleware. Normalement un middleware fait partie d'une chaîne de middlewares. La requête entrante est passée au premier qui la traite ou la passe à son suivant, jusqu'à l'épuisement de la chaîne.

L'idée ici est donc de créer un middleware très simple qui va littéralement encadrer la chaine de traitement de sorte à permettre de déterminer un état avant l'émission des données et calculer ainsi les différences en sortie de chaîne (temps, octets envoyés, etc).

Pour cela partons d'un exemple bien stupide que nous initialisons ainsi:

mkdir test; cd test
npm install express

Puis dans le dossier, créez un fichier index.js que nous remplissons comme suit :

var express = require('express')
var app = express()

app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

Là, de base, notre exemple une fois lancé va afficher son coucou dés que l'on ira sur http://localhost:3000. Ajoutons maintenant notre middleware de log.

var express = require('express')
var app = express()

app.use(function(request, response, next) {
  console.log('Je log');
  if (typeof next === 'function') next();
});

app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

Encadrement de la chaîne de middlewares

À l'exécution de l'exemple précédent, le message Je log va arriver avant que le message J'envoie... ne vous parvienne. Aucun intérêt dans notre cas car à ce stade, rien n'a été envoyé et nous ne pourrons donc avoir ni le nombre d'octets émis, ni le code de statut de la page. Pas de souci, une petite modification va inverser la situation.

var express = require('express')
var app = express()

app.use(function(request, response, next) {
  var end = response.end;
  response.end = function() {
    end.apply(this, arguments);
    console.log('Je log');
  }
  if (typeof next === 'function') next();
});


app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

L'astuce est simple, nous allons écraser au début du traitement (car notre middleware est le premier de la chaîne) la fonction response::end qui est invoquée par expressjs au moment de libérer le socket. Bien évidement avant de l'écraser, nous la sauvegardons dans une variable locale au middleware. Nous l'invoquerons ensuite dynamiquement via end.apply(this, arguments) lorsque notre end sera appelé pour qu'expressjs n'y voit que du feu.

La trace en console est collée juste après cet appel de sorte à ce que si nous lançons maintenant l'exemple, le message Je log arrive bien après j'envoie.

middleware final

C'est presque gagné, il ne nous reste plus qu'à coder les statistiques.

Notez que vous devez en plus installer le paquet microtime pour que ce qui suit fonctionne.

var express = require('express')
var microtime = require('microtime');
var app = express()

app.use(function(request, response, next) {
  var end = response.end;
  request.stats = {
    temps: microtime.now(),
    octets: request.socket.bytesWritten
  }
  response.end = function() {
    end.apply(this, arguments);
    var octets = request.socket.bytesWritten-request.stats.octets;
    var temps = microtime.now()-request.stats.temps;
    console.log('Octets envoyés : %d', octets);
    console.log('Temps pris     : %d', temps);
    console.log('Code de retour : %d', response.statusCode);
  }
  if (typeof next === 'function') next();
});

app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

Et voilà, nous avons à chaque exécution de requête, le nombre d'octets envoyés, le temps pris en microsecondes, et le code de retour. Le principe a été d'ajouter en plus de l'écrasement de la fonction request::end un bloc de données stats que l'on colle directement à l'objet request. Son objectif est de permettre la différence d'état avant/après (surtout pour le temps, car logiquement, le nombre d'octets est toujours 0).

Ensuite dans notre fonction end, et après avoir exécuté la fonction end d'expressjs on effectue nos petits calculs et on affiche les résultats.

Conclusion

Il est possible d'aller bien plus loin dans les données collectées. L'objet Socket dispose notamment des données lues (champ bytesRead). Perso, j'ai simulé ainsi les logs apache (access.log) de sorte à permettre à mes applications d'être analysés par des outils comme awstats. C'est ce qui m'a donné l'idée de partager cette astuce.