Chroniques de la performance : À propos de contentions…

J’ai été, il y a peu, confronté à un problème de performances que l’on peut qualifier d’intéressant – dans la bouche d’un expert technique, ce mot a généralement tendance à provoquer une bouffée de panique chez les plus chevronnés des managers.

Je vous explique.

Le programme consiste à appliquer massivement un traitement identique à un volume important de données – bref, c’est un batch. Objectif opérationnel : assurer la capacité du système à traiter 50000 dossiers par heure.
L’architecture d’exécution de ce batch est relativement classique : un contrôleur est chargé d’obtenir auprès d’un service métier une liste de dossiers à traiter, de segmenter cette liste en lots, puis de soumettre les lots à un pool de threads qui vont réaliser les traitements en parallèle – chaque lot est traité dans une transaction distincte. Le traitement unitaire d’un dossier est relativement long, de l’ordre de 2 secondes ; les lots sont donc petits – 4 dossiers – pour limiter la durée des transactions.

Au-delà de son rôle de segmentation et de répartition des lots, le contrôleur fournit un ensemble de services de pilotage, qui n’ont pas vraiment de relation avec notre problème, mais que je mentionne pour information : état d’avancement du traitement, interruption, reprise, calcul de statistiques variées, rapports d’erreurs, etc.

Typiquement, avec une telle architecture, le débit total du système est une fonction du temps de traitement unitaire et du nombre de threads simultanés :

Débit Horaire = (3600 / Temps Unitaire) * Nombre de threads

Pour mon batch, le calcul théorique est simple : le traitement de chaque dossier demandant 2 secondes, un thread peut traiter 1800 dossiers par heure. Le débit cible étant de 50000 dossiers par heure il est donc théoriquement nécessaire de démarrer un pool de 30 threads.
Ce calcul cependant part d’une hypothèse audacieuse : il suppose que les temps de traitement unitaire resteront stables quel que soit le nombre de threads. En somme, que la montée en charge du système est parfaitement linéaire.

Or les tests grandeur réelle réalisés en pré-production montrent un comportement assez éloigné de notre équation platonicienne :

Exprimé sous forme de débit, ce même graphe montre une pente inquiétante :

Le débit horaire s’écarte de plus en plus de la valeur théorique idéale et tend vers une valeur désespérément éloignée du débit cible. Pire, il aurait tendance à se dégrader lorsque le nombre de threads devient trop élevé. Pas de panique, cependant, ce comportement ne saurait déstabiliser le briscard de la performance que je suis : de telles courbes révèlent simplement que le système atteint une limite qui interdit la montée en charge. Reste à déterminer quel composant physique ou logiciel en est à l’origine.

La première réaction est naturellement de vérifier qu’aucun composant physique n’arrive à saturation. Les outils ad hoc sont utilisés pour contrôler la consommation CPU, l’overhead du GC, le paging, la bande passante, les I/O disque, etc., je vous épargne le détail. Deux éléments intéressants sont tirés de cette analyse : premièrement, aucun composant physique n’approche ses limites de capacité ; deuxièmement, leur niveau de charge épouse presque parfaitement l’évolution du débit présenté dans la figure 2. En d’autres termes, l’usage des ressources physiques, par exemple la charge moyenne des processeurs, présente la même évolution que le débit : leur montée en charge est freinée et s’écarte inexorablement de la progression théorique linéaire.
Une nouvelle fois, ce sont des caractéristiques relativement communes des systèmes parallélisés : cela signifie que les threads d’exécution entrent en compétition pour obtenir certains verrous, ou pour accéder à certaines sections critiques ; plus le nombre de threads augmente et plus la compétition devient serrée : il faut de plus en plus de temps pour acquérir les verrous.

Dans notre système, deux composants sont susceptibles de créer ces conditions :

• la base de données, qui gère des verrous à différents niveaux
• le code java, au travers de blocs synchronisés

Quiconque a déjà travaillé sur un système transactionnel fortement parallélisé sait que les contentions sur la base de données en sont le principal écueil. Pour assurer l’isolation des transactions, les SGBD posent des verrous en lecture et/ou en écriture sur des lignes, des pages ou des tables – en cas de très forte charge, la granularité des verrous est parfois modifiée dynamiquement, passant par exemple de la ligne (ROW LOCK) à la page (PAGE LOCK).
Notre système batch a été conçu en conséquence : la base est partitionnée selon des axes fonctionnels stricts, les opérations de lecture et d’écriture ont été soigneusement séquencées, les verrous sont posés au niveau des pages et le contrôleur sait exploiter certaines caractéristiques du stockage physique pour calculer et répartir les segments entre les différents threads. Une analyse des contentions sur la base de données a démontré l’efficacité de ces stratégies : le niveau de contention reste remarquablement bas, et n’explique en aucun cas la forte dégradation observée lors de la montée en charge.

Reste une seule explication : des contentions dans les couches d’exécution Java. Et une question : comment identifier l’origine de ces contentions, et les corriger ?

Un premier test est réalisé pour valider l’hypothèse de contentions applicatives dans le code java : il consiste à démarrer 5 processus dotés chacun d’un pool de 4 threads – un total de 20 threads, donc, permettant d’atteindre un taux de parallélisation qui dans nos tests précédents mettaient fortement en exergue la dégradation des temps de traitements unitaires. Ce test est concluant : distribués sur 5 processus distincts, les threads ne sont plus soumis à une compétition mortifère, et la montée en charge se réalise de façon satisfaisante.

Une solution envisageable serait d’adopter cette architecture, et de distribuer les traitements sur plusieurs processus. Le contrôleur, cependant, n’a pas été conçu pour coordonner plusieurs processus. L’évolution la plus simple, consistant à séparer le contrôleur des composants métiers – par exemple au moyen d’EJBs – implique d’introduire une couche de distribution qui nous semble d’autant moins souhaitable que le contrôleur est en charge du pilotage des transactions : le séparer des traitements signifie distribuer les transactions, et tous les petits soucis que cette décision implique généralement. Cela signifie aussi probablement l’introduction d’un serveur d’applications dans l’architecture de batch, avec les difficultés afférentes en terme de déploiement et d’exploitation. D’autres évolutions plus massives sont envisageables : par exemple s’appuyer sur des tables techniques pour stocker les segments, et découpler complètement une phase de pré-processing – consistant à calculer les lots – et une phase de traitement – consistant à piocher des lots dans la base et à les traiter. On peut même imaginer des solutions plus exotiques, à base de files JMS… Mais pour tout dire, nous aimons la compacité de notre architecture initiale, et ne sommes pas prêts à l’abandonner sans résister un peu. La question reste donc entière : comment débusquer l’origine de nos contentions aux fins de les liquider ?

L’analyse statique du code n’a rien donné : le contrôleur, à l’instar des composants métiers, utilise un bon zillion de bibliothèques tierces, plus ou moins open source et au flot d’exécution volontiers cryptique. Impossible dans ces conditions de déterminer l’origine exacte des contentions par simple consultation des sources : une analyse runtime est nécessaire.

Reste à trouver le bon outil dans la sacoche du plombier java. Même avec l’aide gracieuse de Google, la récolte reste maigre en matière d’outillage…

Autant l’offre est pléthorique lorsqu’il s’agit de profiler la consommation CPU ou mémoire des applications Java, autant l’analyse des contentions reste une discipline peu outillée. Certes les profilers java offrent pour la plupart un module d’analyse de threads ; mais leur overhead est tel qu’il est difficile, voire impossible d’instrumenter un traitement fortement multi-threadé comme notre batch : au-delà de 3 ou 4 threads, les informations collectées perdent de leur pertinence, et les temps unitaires s’allongent tellement que toute tentative d’analyse relève de l’acrobatie la plus pure.
Tordons rapidement le cou à hprof, le profiler intégré au JDK – le notre, en l’occurrence, est un JDK IBM 1.4.2 SR8 ; la documentation indique une option « monitor=y », qui, je cite, « tells hprof to generate information on contention monitors used to synchronize the work of multiple threads » (je vous laisse traduire). Bigre, nous voilà sauvés ! Pas tout à fait… Outre que le faire fonctionner a demandé une montée de version du JDK – la version que nous utilisions à l’origine générait un très joli core lors de l’activation de hprof -, les informations obtenues se sont révélées d’une rare inutilité (fondamentalement, un état des moniteurs java au moment de la sortie du processus. Aucun intérêt !).
Exit hprof, donc.
Autre approche : générer de façon répétée des Thread Dump à l’aide de l’instruction kill -3, puis comparer les différents dumps à l’aide d’un outil ad hoc (en l’occurrence un utilitaire disponible sur le site alphaWorks, et dont je donne le nom complet pour souligner le sens du marketing des ingénieurs IBM : IBM Thread and Monitor Dump Analyzer for Java Technology). Bien que prometteuse, cette solution n’a une nouvelle fois pas donné de résultat définitif : elle nous a permis d’identifier quelques méthodes candidates, mais sans qu’il fût possible de quantifier leurs responsabilités respectives.

Reste une solution : retrousser ses manches et écrire un profiler spécialisé en s’appuyant sur JVMPI.
JVMPI (pour Java Virtual Machine Profiling Interface) est, comme son nom le suggère, une API native de profilage de la JVM (remplacée par JVMTI à partir de Java 5, mais c’est une autre histoire). L’API fonctionne sur un système de callback : l’agent (c’est ainsi que l’on nomme le programme s’appuyant sur l’API) s’enregistre auprès de la JVM en précisant les types d’événements dont il souhaite être notifié – vous aurez probablement reconnu le pattern Observer.
Ces événements concernent la plupart des opérations techniques de bas niveau réalisées par la JVM : chargement d’une classe, allocation mémoire, exécution d’une méthode, démarrage d’un thread, etc. Parmi ces événements, deux retiennent particulièrement notre attention : MONITOR_CONTENDED_ENTER et MONITOR_CONTENDED_ENTERED. Le premier indique qu’un thread souhaite exécuter un bloc synchronisé, et tente d’acquérir un moniteur à cette fin (pour mémoire, la notion de moniteur en java est très proche de celle de verrou dans le reste du monde); le second indique que le thread a obtenu le moniteur en question et entame l’exécution du bloc synchronisé. L’intervalle de temps entre les deux événements correspond par conséquent à la durée totale de l’attente – autrement dit à la durée de la contention.
Munis de ces rudiments de JVMPI, il est possible de formuler les spécifications exhaustives de notre petit outil de profilage : la durée de toutes les contentions rencontrées par le programme est mesurée. Si cette durée est supérieure à un certain seuil (disons 5 millisecondes), le nom de la méthode correspondante est loggué dans un fichier, ainsi qu’une pile d’appels simplifiée.

Bien. Il ne reste plus qu’à coder.

Le point d’entrée d’un agent JVMPI est la méthode JVM_OnLoad. C’est dans cette méthode que l’on va informer le sous-système JVMPI des événements que l’on souhaite activer (EnableEvent), et de la méthode callback qui sera invoquée lors des occurrences de ces événements (NotifyEvent) :

JNIEXPORT jint JNICALL _JVM_OnLoad(JavaVM *vm, char *options, void *reserved)
{
    ...

    /* Register callback method */
    jvmpi->NotifyEvent = jtprof_notify_event;
    /* Enable events */
    jvmpi->EnableEvent(JVMPI_EVENT_JVM_SHUT_DOWN, NULL);
    jvmpi->EnableEvent(JVMPI_EVENT_CLASS_LOAD, NULL);
    jvmpi->EnableEvent(JVMPI_EVENT_CLASS_UNLOAD, NULL);
    jvmpi->EnableEvent(JVMPI_EVENT_MONITOR_CONTENDED_ENTER, NULL);
    jvmpi->EnableEvent(JVMPI_EVENT_MONITOR_CONTENDED_ENTERED, NULL);
    jvmpi->EnableEvent(JVMPI_EVENT_THREAD_START, NULL);
    jvmpi->EnableEvent(JVMPI_EVENT_THREAD_END, NULL);

    ...

    return JNI_OK;
}

La méthode callback, jtprof_notify_event, se contente de déterminer la nature de l’événement et de déclencher un handler spécialisé :

static void jtprof_notify_event(JVMPI_Event *event)
{
    switch(event->event_type) {
        case JVMPI_EVENT_JVM_SHUT_DOWN:
            handle_jvm_shut_down_event();
            return;
        ...

        case JVMPI_EVENT_THREAD_START:
            handle_thread_started_event(event);
            return;
        case JVMPI_EVENT_THREAD_END:
            handle_thread_end_event(event);
            return;
        case JVMPI_EVENT_MONITOR_CONTENDED_ENTER:
            handle_monitor_contented_enter(event);
            return;
        case JVMPI_EVENT_MONITOR_CONTENDED_ENTERED:
            handle_monitor_contented_entered(event);
            return;
        ...

    }
}

Les choses semblent relativement simples. L’API JVMPI offre même un système de stockage thread local (méthode GetThreadLocalStorage), permettant de conserver une structure de données quelconque dédiée à chaque thread. Je vous épargne les détails de la création et de la destruction de cette structure de données – les curieux pourront jeter un oeil sur le code source. Sachez simplement qu’elle est créée lors de l’événement THREAD_START, détruite lors de l’événement THREAD_END, et qu’elle permet notamment de conserver la date de la demande d’acquisition du moniteur par le thread.

Au final, le code permettant de mesurer la durée d’acquisition d’un moniteur est relativement trivial :

static void handle_monitor_contented_enter(JVMPI_Event *event){
    thread_local_context *ctx = (thread_local_context*)jvmpi->GetThreadLocalStorage(event->env_id);

    //Error handling code
    ....
    ctx->timer = system_current_time_millis();
}

static void handle_monitor_contented_entered(JVMPI_Event *event){
    long finish = system_current_time_millis();
    long total;

    thread_local_context *ctx = (thread_local_context*)jvmpi->GetThreadLocalStorage(event->env_id);

    //Error handling code
    ....

    total = finish – ctx->timer;
    ctx->timer = 0;
    if (total > __contention_threshold){
        //Log contention details
        ....
    }
}

Les choses, bien sûr, sont en réalité un poil plus complexes – fallait pas rêver, non plus.
Par souci d’efficacité, en effet, la structure de données JVMPI_Event ne contient, pour chaque événement, qu’un jeu minimal d’informations. En pratique, cela signifie que le nom de la méthode invoquée n’est pas disponible sous forme littérale, mais sous la forme d’un identifiant interne créé lors du chargement de la classe correspondante.
Logguer cet identifiant ne serait bien sûr pas d’un grand intérêt. Il faut pouvoir l’associer au nom qualifié de la méthode. Pour cela, l’événement CLASS_LOAD doit être traité. Cet événement fournit la définition complète de la classe et de toutes ses méthodes – y compris leur nom littéral. Notre programme conserve donc ces informations dans un tableau associatif (dont le code source est très largement inspiré de celui de hprof). Ce tableau peut ensuite être consulté lors du traitement d’une contention afin de déterminer le nom de la méthode appelante à partir de son identifiant. Une technique similaire est mise en oeuvre pour expliciter la pile d’appels. Je vous laisse consulter le code source pour les détails…

Le programme doit être compilé sous forme de bibliothèque dynamique (extension .dll sous Windows, .so sous Unix), inclu dans le LIB_PATH (ou son équivalent) et intégré à la JVM grâce à l’option -Xrunjtprof (jtprof est le nom donné à la bibliothèque). Voici le type de sorties obtenues :

[JTPROF] Contention report [id=-2002923824,thread=Contention-Thread-4,blocked=305ms]
[JTPROF] Stack trace:
[JTPROF]	 org.test.Contentions.blockABitMore (Contentions.java:36)
[JTPROF]	 org.test.Contentions.run (Contentions.java:25)
[JTPROF]	 java.lang.Thread.run (Thread.java:595)
...
[JTPROF] Thread end [id=-2002912512, name=Contention-Thread-6, duration=1519ms, blocked=1416ms]

Une fois mis au point, cet outil s’est révélé très précieux. Son overhead est très faible – les événements les plus gourmands, comme les sites d’allocation mémoire ou la consommation CPU des méthodes, ne sont pas traités. Il nous a fourni un état très précis du niveau de contention, et de la localisation de celles-ci. Une douzaine de méthodes ont été corrigées (la plupart des contentions étaient de très courte durée – rarement plus de 50ms – mais leur fréquence et leur durée avaient tendance à augmenter).
Au terme de ces optimisations, la courbe des débits se présente comme suit :

Il reste un léger décrochage au-delà de 25 threads, mais cette fois-ci, son origine ne fait pas de doute : notre machine de test est simplement saturée, et la contention, cette fois-ci, porte sur l’accès aux processeurs.

Ceux qui ont suivi depuis le début se souviennent peut-être de l’équation présentée plus haut dans cet article :

Débit Horaire = (3600 / Temps Unitaire) * Nombre de threads

S’ils n’ont pas complètement oublié le programme de mathématiques du Brevet des Collèges, ils auront probablement compris que l’augmentation du nombre de threads n’est pas le seul levier du débit : réduire le temps de traitement unitaire en est un autre. Mais ceci est une autre histoire…