Drupal core, les hooks, les groupes, et un cache désastreux

Share and options

Dans un article précédent je vous ai présenté la gestion des caches d'une manière assez théorique  Je ne pensais pas que ce matin même j'allais tomber sur un très bon exemple d'une mauvaise gestion de cache, et je pensais encore moins la trouver dans le core. Cet article va présenter, d'une façon aussi objective que possible, l'anatomie de ce cache particulier, et pourquoi même si l'idée était bonne théoriquement, elle s'est en réalité avérée catastrophique dans mon cas d'utilisation. Je vais dans les paragraphes suivants qualifier cette gestion de cache de réel bug.

1. Contexte

Le site sur lequel je travaille actuellement est un site Drupal Commerce. Un des aspect primant des sites de Commerce est qu'ils sont censés pouvoir supporter de lourdes charges d'utilisateurs connectés simultanément (ce qui n'est pas le point fort de Drupal) mais aussi vont être sujet d'un grand nombre d'écritures de données, en ce qui concerne surtout la gestion du panier des utilisateurs.

Comme on pouvait s'y attendre Drupal est une application web  Les diverses modifications de données – donc assez nombreuses dans notre contexte – se produiront essentiellement lors de requêtes HTTP POST. Ce n'est pas important tout de suite, mais ça le sera plus tard.

2. Symptômes

Comme tous les jours, je dédiais aujourd'hui une bonne demi-heure matinale au profiling du site sur lequel je travaille  Ce dernier étant voué à supporter une charge de 150 utilisateurs connectés naviguant simultanément sur le site, je ne peux me permettre de laisser quelconque regression en terme de performance arriver, les conséquences pourraient être dramatiques1. Je dédiais ce matin à la recherche d'indices à propos d'un sujet épineux : le scénario donnant les plus mauvais temps de réponse lors des tests de montées en charge est celui de la constitution d'un panier à partir d'un formulaire de saisie de commande rapide.

En consultant cette trace, j'ai pu remarquer une chose n'étant pas forcément lié aux lenteurs, mais tout de même étonnante  la fonction php::is_file() était appellée plus de 700 fois lors de la soumission de mon formulaire spécifique. En remontant la trace, j'ai pu reconstituer deux scénarios différents d'appel de cette fonctions, les deux aboutissant à l'appels de ces trois fonctions :

  • module_implements()
  • module_load_include()
  • php::is_file()

Note : la notation php:: est emprunté des traces d'Xdebug, ceci signifie que c'est la fonction interne à PHP is_file() qui est appellée. Ces trois appels l'un après l'autre constituent le plus petit dénominateur commun de ces 700 appels.

3. Anatomie

3.1. Les « groupes » de hooks

Vous devez savoir, avant de commencer à lire ce chapitre, que le core cache dans un object de cache binaire l'ensemble des hooks implémentés par les modules. Ceci permet plusieurs choses mais la plus importante d'entre elle est qu'elle évite d'itérer sur la liste des modules durant l'exécution normale du site et permet entre autre à l'appel de ces hooks d'être plus rapide. Mais un autre détail est tout aussi important bien que très souvent méconnu des gens.

La notion de « groupes » est née avec Drupal 7 . Le principe est relativement simple, prenons la Field API par exemple : afin de définir un type de champs, vous devez définir un grand nombre de hooks, comme par exemple :

  • hook_field_info()
  • hook_field_formatter_info()
  • hook_field_widget_info()
  • etc…

Lors de la plupart des exécutions de pages, charger le code de ces dernier n'a que peu d'intérêt. Ils seront appelés que lors de l'affichage d'une entité ayant un de ces champs – certains même que lorsque vous ouvrirez le formulaire d'édition de cette entité – et par conséquent il serait dommage de les laisser vivre dans le fichier .module de votre module (qui lui sera chargé pour toutes les pages)2.

Le principe du groupe est de grouper arbitraire à un certain nombre de hooks liés, pour les encapsuler dans un fichier spécifique. Le module qui les définit les hooks définit aussi les groupes associés, il signale à Drupal d'aller les chercher dans ce fichier si nécessaire (appellé module.groupe.inc). Ceci bien sûr est optionnel, et vos hooks peuvent vivre dans votre fichier .module si vous ne voyez pas l'intérêt de les désolidariser du reste de votre code.

Le problème d'une telle fonctionnalité c'est que lorsque que le cœur cherche si un module implémente ou non un des ces hooks il est obligé de tester si le fichier existe, pour chaque module activé sur votre site, d'où l'appel à php::is_file().

On peut le voir dans le code suivant, includes/module.inc, ligne 631 :

  if (!isset($implementations[$hook])) {
    // The hook is not cached, so ensure that whether or not it has
    // implementations, that the cache is updated at the end of the request.
    $implementations['#write_cache'] = TRUE;
    $hook_info = module_hook_info();
    $implementations[$hook] = array();
    $list = module_list(FALSE, FALSE, $sort);
    foreach ($list as $module) {
      $include_file = isset($hook_info[$hook]['group']) && module_load_include('inc', $module, $module . '.' . $hook_info[$hook]['group']);
      // Since module_hook() may needlessly try to load the include file again,
      // function_exists() is used directly here.
      if (function_exists($module . '_' . $hook)) {
        $implementations[$hook][$module] = $include_file ? $hook_info[$hook]['group'] : FALSE;
      }
    }
    // Removed some code here...
  }

On voit bien que ce bout de code appelle la fonction module_load_include(), qui à sont tour appellera la fonction is_file() (ce que je n'ai pas affiché ici).

3.2. Le caching des hooks

L'appel de cette fonction is_file() est couteuse, elle effectue un I/O sur le système de fichier en dessous, quant bien même votre système d'exploitation sait cacher ces informations de manière intelligente, il est très déconseillé d'en abuser lors de l'exécution de vos scripts. C'est pourquoi Drupal va cacher toutes ces informations. Lors du premier accès à un hook particulier, s'il ne le connaît pas, il déterminera à chaud si le fichier existe ou non, et s'il existe le chargera ; Pour éviter que ceci ne se produise toujours, à chaque nouveau hook appellé, il placera l'information de son existence3 dans un cache, qu'il sauvegarde ensuite à l'aide d'une fonction : module_implements_write_cache().

L'appel de la fonction module_implements_write_cache() est délayée en fin de vie du script, pour deux raisons :

  • Elle est ainsi appellée qu'une seule fois pour toute la page, même si plusieurs nouveaux hooks ont étés trouvés, ceci afin d'éviter de nombreuses requêtes d'écriture inutiles.
  • Elle s'exécute qu'une fois la page complètement rendue et les flux de sorties vidés, ceci permettant au serveur HTTP d'envoyer la page avant même la fin de l'exécution de PHP.

On peut trouver l'appel de cette fonction à un seul et unique endroit, dans includes/common.inc, ligne 2555 :

function drupal_page_footer() {
  global $user;

  module_invoke_all('exit');

  // Commit the user session, if needed.
  drupal_session_commit();

  if (variable_get('cache', 0) && ($cache = drupal_page_set_cache())) {
    drupal_serve_page_from_cache($cache);
  }
  else {
    ob_flush();
  }

  _registry_check_code(REGISTRY_WRITE_LOOKUP_CACHE);
  drupal_cache_system_paths();
  module_implements_write_cache();
  system_run_automated_cron();
}

Mais tout ceci n'explique en rien la source du bug.

3.3. Le premier coupable (oui, le premier)

Une longue explication ne sera pas nécéssaire, voici le code en question, dans includes/module.inc, ligne 765 :

function module_implements_write_cache() {
  $implementations = &drupal_static('module_implements');
  // Check whether we need to write the cache. We do not want to cache hooks
  // which are only invoked on HTTP POST requests since these do not need to be
  // optimized as tightly, and not doing so keeps the cache entry smaller.
  if (isset($implementations['#write_cache']) && ($_SERVER['REQUEST_METHOD'] == 'GET' || $_SERVER['REQUEST_METHOD'] == 'HEAD')) {
    unset($implementations['#write_cache']);
    cache_set('module_implements', $implementations, 'cache_bootstrap');
  }
}

Souvenez-vous, mes problèmes de montée en chargent se produisaient principalement lors du HTTP POST de mes formulaires. En effet, si vous lisez bien ce code (et si vous parlez un tant soit peu anglais) vous remarquerez qu'il ignore délibéremment de cacher les hooks lorsque la requête HTTP est une requête POST.

En réécrivant cette fonction de la sorte, j'ai cru pouvoir m'en sortir :

function module_implements_write_cache() {
  $implementations = &drupal_static('module_implements');
  unset($implementations['#write_cache']);
  cache_set('module_implements', $implementations, 'cache_bootstrap');
}

Je pense, et je ne suis pas objectif ici, que la personne qui a pris cette décision n'a jamais effectué aucune mesure significative. En effet, ce qu'il dit dans son commentaire est probablement vrai pour tous les sites n'ayant pas comme vocation d'avoir ni un fort traffic d'utilisateurs connectés, ni un grand nombre de formulaires métier : j'aurais tendance à dire qu'en ce sens cette personne était probablement très intelligente, car Drupal est un CMS, et non un framework (contrairement à ce que beaucoup aimeraient) et son principal métier est de cracher du contenu.

Cependant, ce raisonnement n'a pas été assez développé : si le métier du site courant est bien de cracher du contenu, toutes les pages seront probablement stoquées dans des caches de page plus précoces, ce qui contrecarre le besoin d'avoir des caches au niveau de quelconque API. Dans un tel site, 99% des pages servies aux utilisateurs ne seront que des relicats de générations ultérieures  Dans ce contexte précis on peut se permettre d'optimiser une telle API pour les écritures, puisque ces dernières seront les seules aboutissant à une vraie génération de page.

Mais revenons à notre analyse ! C'est surpris que j'ai pu constater qu'une fois ceci effectué, mon problème n'était absolument pas résolu…

3.4. Et pas des moindres, le second coupable !

En continuant mon déboggage pas-à-pas minutieux, j'ai été surpris de voir que même après la correction de cette fonction, elle n'était bêtement jamais appellée. Malgré une minutie toute particulière quant au debug pas-à-pas4, je pense que je ne m'en saurais pas sorti si je n'avais pas une bonne connaissance du cœur : la fonction drupal_page_footer() est particulière, c'est le garant que l'exécution de Drupal sera terminée proprement. Terminer l'exécution de l'application est un passage très délicat, il y'a en effet un grand nombre de détails à maîtriser, comme la sauvegarde des données de la session si nécéssaire. Le sujet d'aujourd'hui n'étant pas l'architecture d'une application web, je ne vais pas m'étaler sur le sujet.

Un cas particulier existe dans Drupal, une version légère de drupal_page_footer() existe et est censée être plus rapide, elle est exécutée plus particulièrement dans le contexte des HTTP POST, c'est la fonction drupal_exit(), présente dans le fichier includes/common.inc, ligne 2588 :

function drupal_exit($destination = NULL) {
  if (drupal_get_bootstrap_phase() == DRUPAL_BOOTSTRAP_FULL) {
    if (!defined('MAINTENANCE_MODE') || MAINTENANCE_MODE != 'update') {
      module_invoke_all('exit', $destination);
    }
    drupal_session_commit();
  }
  exit;
}

On remarquera que cette fonction n'appelle pas module_implements_write_cache(), surement pour la même raison que le commentaire énoncé dans la version originale de cette dernière. Je vais passer un peu sur l'objectivité et postuler que c'est probablement une erreur de conception : les contextes HTTP GET et POST sont effectivement très différents, mais il n'y a dans l'absolu aucune raison de terminer la requête differement ici : la fonction drupal_exit() sera souvent appellée lors qu'on renvoie une code HTTP redirect, et aucune sortie ne sera écrite dans la réponse HTTP, nous pouvons donc assurer la fermeture normale de l'exécution de la même façon que pour une réponse traditionnelle.

J'ai opté pour une façon malpropre dans ce projet en particulier pour solutionner le problème. J'ai commencé par écrire une fonction particulière :

function _drupal_close_request($destination = NULL) {

  if (!defined('MAINTENANCE_MODE') || MAINTENANCE_MODE != 'update') {
    module_invoke_all('exit', $destination);
  }

  // Commit the user session, if needed.
  drupal_session_commit();

  if (!$destination && variable_get('cache', 0) && ($cache = drupal_page_set_cache())) {
    drupal_serve_page_from_cache($cache);
  }
  else {
    while (0 < ob_get_level()) {
      ob_end_flush();
    }
  }

  _registry_check_code(REGISTRY_WRITE_LOOKUP_CACHE);
  drupal_cache_system_paths();
  module_implements_write_cache();
  system_run_automated_cron();
}

Notez que j'ai aussi corrigé d'éventuel avertissements PHP liés au possibles tentatives de vidage de flux non existants.

Puis j'ai réécris respectivement les deux fonctions drupal_page_footer() et drupal_exit() de la sorte :

function drupal_page_footer() {
  _drupal_close_request();
}

function drupal_exit($destination = NULL) {
  _drupal_close_request();
  exit;
}

Notez que j'ai de plus conservé mon implémentation modifiée de module_implements_write_cache() :

function module_implements_write_cache() {
  $implementations = &drupal_static('module_implements');
  unset($implementations['#write_cache']);
  cache_set('module_implements', $implementations, 'cache_bootstrap');
}

Et je n'ai maintenant plus aucun problème : je me suis définitivement débarassé de mes 700 appels à la fonction is_file(). Notez aussi que lors de l'analyse de ce bug, j'ai aussi découvert l'exécution de deux default rules par le module Commerce particulièrement couteuses, dont je me suis débarassé par la même occasion en hardcodant dans un module métier leur comportement.

Il est a noter que la solution propre, a mon avis, est de patcher tout ce petit monde est d'utiliser la fonction drupal_register_shutdown_handler(), qui à été faite pour ça. Ceci sous entend que cet enregistrement devra être fait très tôt dans le bootstrap de Drupal, et c'est une modification plus difficile à faire accepter que de simplement partager le code de ces deux fonctions modifiées.

4. Conclusion

Je ne peux en vouloir à l'auteur du code d'origine, l'analyse qu'il en a fait était assez correcte, cependant je lui en veux car je pense qu'il a commis une erreur de conception : quand une application est sujette à des utilisations très hétérogènes, il est très difficile d'avoir raison quand on produit des optimisations qui ne tiennent compte que d'un seul cas d'utilisation réel. Je pense que l'auteur de ces lignes à fait une erreur de jugement, certe assez anodine, mais qui reveille un comportement dangereux et qui lui n'est pas anodin.

Ce genre d'analyse d'impact de performance n'est pas dure à effectuer, c'est détecter les symptômes à l'origine qui le sont, et je pense qu'aujourd'hui beaucoup de sites Commerce (entre autre) pourraient en souffrir, et ceci va probablement durer très longtemps avant que quelqu'un d'autre se reveille pour corriger ceci.

Je n'ai pas encore posté de bug pour Drupal, je vais bien entendu le faire d'ici peu. Je redoute cependant que les mainteneurs refusent, et ceci pour deux raisons :

  • Mes changements pourraient induire de mauvais comportement sur des sites existant qui détournent l'utilisation des fonctions que j'ai modifiées.
  • Le fait que Drupal 8 ai lui aussi fusionné ces deux fonctions peut potentiellement leur servir d'excuse pour ne pas vouloir le faire dans Drupal 7.

Merci à asyd (#drupal-fr@irc.freenode.net) pour les corrections.

  1. Petite note à ce sujet, le site pour l'instant fonctionne comme un charme sur un quad core avec 4Go de RAM, ce qui est plutôt positif Back to text
  2. Dans le monde réel, on utilise des OPCode cache, que le code soit dans ce fichier ou ailleurs n'est pas significatif en terme de performance. C'est surtout plus lisible. Back to text
  3. Son existence ou sa non-existence, pour éviter de réitérer dans le vide. Back to text
  4. Le meilleur ami du développeur est le débogueur pas-à-pas de son choix. Back to text