Qu'est-ce qui met ces octets sur le fil?

Un graphique qui n'a aucun sens au premier coup d'oeil. Sur les noeuds frontaux d'un cluster en production que j'aide à opérer, l'interface de stockage privée, celle qui porte le trafic CephFS, recevait de 4 à 12 fois plus d'octets que l'interface publique où arrivent les requêtes clientes. Ces machines existent pour accepter des requêtes entrantes. Elles devraient écrire vers le stockage, à la rigueur. Au lieu de ça, le réseau de stockage avalait un torrent de lectures.

Donc: qu'est-ce qui met ces octets sur le fil? Je ne voulais pas une histoire plausible. Je voulais un chiffre que je pourrais défendre quand quelqu'un qui connaît le noyau mieux que moi viendrait le titiller.

Voici comment j'ai obtenu ce chiffre, y compris le passage où mon propre instrument m'a menti d'un facteur trente et où j'ai fait confiance au compteur à la place.

Choisir le seul chiffre qui ne peut pas mentir#

Choisissez ce en quoi vous avez confiance avant de commencer à collecter des données, parce qu'à la minute où vous avez des données, vous serez tenté de faire confiance à ce qui a été le plus facile à collecter.

Sur un montage CephFS, le client noyau tient un bloc de métriques dans debugfs:

cat /sys/kernel/debug/ceph/*/metrics
# read total_sz: bytes actually pulled from the OSDs
# write total_sz: bytes actually pushed to the OSDs

read total_sz, ce sont les octets que le client a physiquement récupérés des démons de stockage objet (OSD). Pas les octets qu'une application a demandés. Pas les octets revenus de la cache. Les octets qui ont traversé le réseau de stockage parce qu'il le fallait. Immunisés contre les succès de cache, le timing asynchrone, les rafales, parce que c'est incrémenté à l'endroit où les octets quittent l'OSD et atteignent le client. Si un autre chiffre est en désaccord avec ce compteur, c'est l'autre chiffre qui a tort, jusqu'à preuve du contraire.

Tout le reste, les noms de processus, les chemins de fichiers, quel PID lisait, je l'ai traité comme de l'attribution. L'attribution est une hypothèse sur qui a causé les octets. Ce n'est pas la mesure des octets. Garder ces deux idées dans des boîtes séparées, c'est toute la méthodologie.

Le piège de la cache#

La première mauvaise réponse est apparue vite.

L'endroit évident où s'accrocher, c'est ceph_read_iter, le point d'entrée VFS pour une lecture sur un fichier Ceph. On le sonde, on additionne les octets, on attribue au processus. J'ai fait un test de cohérence en passant md5sum sur un fichier de carte partagé que je savais déjà en cache sur le noeud, et j'ai vu la sonde rapporter 203 Mio de lectures.

Ça a failli atterrir dans le rapport comme de la charge. Ça a exactement la forme d'une trouvaille: gros fichier, vrai processus, gros compte d'octets. Le problème, c'est que ceph_read_iter compte les succès de cache. Ces 203 Mio n'ont jamais touché les OSD. Le compteur debugfs a à peine bougé pendant ce md5sum. J'avais mesuré la demande VFS et je l'avais appelée trafic sur le fil, ce qui est exactement l'erreur que la discipline ci-dessus existe pour prévenir.

Le correctif a été d'arrêter de mesurer la demande et de commencer à mesurer la récupération. J'ai séparé deux choses que la première sonde avait mélangées: ceph_read_iter pour ce que l'application a demandé, et le chemin de lecture anticipée pour ce que le client a réellement préchargé depuis les OSD. Avec les deux, je pouvais calculer un pourcentage de succès de cache par fichier, et la carte partagée en cache est sortie de la colonne « charge » où elle n'avait jamais sa place. Elle lit, à la couche application, énormément. Elle met presque rien sur le fil.

L'amplificateur#

Une fois que je mesurais la récupération au lieu de la demande, le chiffre central est sorti d'un seul fichier:

cat /sys/class/bdi/ceph*/read_ahead_kb
# 8192

8 Mo de lecture anticipée sur chaque montage CephFS. Quand un processus lit quelques octets à travers un descripteur de fichier, le noyau ne va pas chercher quelques octets. Il en récupère jusqu'à 8 Mo d'avance, sur la théorie que vous voudrez les octets suivants bientôt. Pour une charge de travail qui diffuse de gros fichiers en séquentiel, c'est un cadeau. Pour une charge de travail qui tâtonne sur de minuscules fichiers, c'est une catastrophe: chaque lecture de la taille d'un octet traîne jusqu'à 8 Mo hors des OSD.

C'est ça, l'amplification. Mesurée par rapport aux opérations de lecture réelles, ça donnait environ 147 Kio tirés par lecture, à peu près 13 fois les octets que l'application demandait. Et ça explique la forme de tout le graphique:

Les lectures dominent les écritures structurellement, pas à cause d'un pic. Le travail de stockage de ces noeuds, c'est des recherches de config par entité, pas des écritures en masse. Ratio cumulé proche de 31 pour 1: 906 Go lus contre 29 Go écrits. L'interface privée reçoit environ 19 fois ce qu'elle transmet. Le réseau de stockage n'a jamais fait du stockage de la façon que son nom suggère. Il répondait à un déluge de minuscules recherches de config, chacune gonflée de 13x par la lecture anticipée.

Pourquoi un noeud frontal lit-il du stockage partagé en premier lieu#

Question légitime: pourquoi ces noeuds touchent-ils CephFS sur le chemin de lecture? Un noeud qui ne ferait que transmettre des requêtes ne le ferait pas. Mais ceux-ci ne font pas que transmettre, ils prennent une décision par requête, et cette décision a besoin de configuration. Chaque requête entrante doit lire une poignée de petits fichiers de config par entité depuis le stockage partagé avant de pouvoir agir. Ça fait environ 0,65 Mio tirés par requête, et rien de tout ça n'est de la charge utile en masse. Ces noeuds ne lisent jamais de gros objets depuis CephFS. Ils lisent de minuscules fichiers de config par entité, et la lecture anticipée de 8 Mo gonfle chaque lecture de config de la taille d'un octet en un gros transfert sur le fil.

Ventilé par ce que le chemin par requête touche réellement:

identity / auth lookups           ~19-22%
limits / policy data              ~22%
per-entity rules                  ~19%
periodically refreshed shared map ~7%   (mostly cache hits)

La carte partagée, c'est le fichier qui a failli me berner dans le piège de la cache. Lue constamment, servie presque entièrement depuis la cache, donc elle apparaît grosse en demande et petite sur le fil. Avoir le pourcentage de succès de cache en main faisait qu'elle s'asseyait dans la bonne colonne cette fois.

Quand les grosses lectures ne sont pas du tout la charge de travail#

Il y avait un deuxième motif dans les données qui ne collait pas aux « recherches de config par requête », et il aurait eu l'air de bruit si j'avais fait la moyenne sur tous les noeuds.

Certains noeuds lisaient de 6 à 11 Mio/s, environ 4,7 Mio par requête, un ordre de grandeur au-dessus de la base de référence des recherches de config. D'autres étaient légers. La répartition ne suivait pas le volume de requêtes. Elle suivait l'état de migration. Une tâche de réplication en arrière-plan lit en masse des objets de données complets sur les noeuds où elle tourne, et les noeuds chargés étaient exactement ceux qui étaient encore en cours de migration. Le noeud qui avait fini de basculer était léger.

Ça donnait une prédiction falsifiable, le genre que j'aime parce que c'est le genre qui peut vous mettre dans l'embarras plus tard si vous vous êtes trompé: une fois que les clusters restants finiront de basculer, leur taux de lecture chutera à la base de référence légère. Pas « devrait s'améliorer ». Chute à une base de référence précise que j'avais déjà mesurée sur le noeud qui avait fini.

Le mensonge de facteur 30 dans mon propre outil#

Maintenant le passage qui compte le plus, parce que c'est celui que je suis le moins à l'aise de raconter et donc celui qui vaut le plus la peine d'être raconté.

Pour faire l'attribution correctement, j'avais écrit un profileur sur mesure, bpftrace alimentant un petit agrégateur Go, qui s'accrochait à ceph_readahead et lisait la taille de la fenêtre de lecture anticipée dans la structure readahead_control qu'on lui passe:

kprobe:ceph_readahead
  $rac = (struct readahead_control *)arg0;
  $pages = $rac->_nr_pages;     // window size, in pages
  // attribute $pages * 4096 to the current process

Raisonnable en apparence. Le problème, c'est que ce noyau utilise la couche netfs, et netfs étend la fenêtre de lecture anticipée après l'entrée dans ceph_readahead, dans ceph_netfs_expand_readahead. Donc _nr_pages à l'entrée de ceph_readahead, c'est la taille avant expansion. Ma sonde capturait la fenêtre avant que le noyau ne la fasse grandir, sous-comptant d'environ 30x les octets qui atteignaient réellement les OSD.

Je savais qu'elle avait tort parce qu'elle était en désaccord avec le compteur debugfs. Le compteur disait une chose, mon profileur disait environ un trentième de cette chose, et la règle que j'avais posée au départ, c'est que le compteur gagne. Mon instrument avait tort jusqu'à ce que je puisse prouver qu'il avait raison, et je ne le pouvais pas, donc il avait tort.

Le correctif a été d'ancrer la sonde plus profond, sur la fonction mm centrale page_cache_ra_unbounded, qui s'exécute après que la fenêtre est finalisée. Deux raisons pour lesquelles ça marche là où l'ancien accrochage échouait. Premièrement, elle est présente dans le BTF de ce noyau, donc bpftrace peut s'y attacher et lire ses arguments par type. Deuxièmement, son argument readahead_control porte le pointeur de fichier, ce qui me permet d'atteindre l'inode et le superbloc et de filtrer vers CephFS par le nombre magique du superbloc:

kprobe:page_cache_ra_unbounded
  $rac = (struct readahead_control *)arg0;
  $sb = $rac->file->f_inode->i_sb;
  if ($sb->s_magic == 0x00c36400) {        // CEPH_SUPER_MAGIC
      $bytes = arg2 * 4096;                 // post-expansion nr_to_read
      // now attribute, knowing the window is final
  }

Après avoir déplacé l'ancre, le total du profileur s'est réconcilié à environ 170 Mo sur 6 minutes, à peu près 471 Ko/s, et il correspondait exactement au delta du compteur debugfs. Pas approximativement. Le delta. Ensuite une comparaison à trois: le compteur debugfs, /proc/net/dev sur l'interface de stockage, et la base de données chronologique qu'on avait déjà, tous d'accord à 6 pour cent près. À ce moment-là, l'attribution était digne de confiance, parce que le total qu'elle additionnait était le chiffre auquel je faisais déjà confiance.

La raison pour laquelle les traces mentent sur le qui#

Un dernier piège qui vaut la peine d'être nommé, parce que c'est la raison pour laquelle l'attribution est difficile même après que le compte d'octets est correct.

J'avais envisagé d'attribuer les lectures en traçant openat, en faisant correspondre les chemins ouverts aux processus qui les avaient ouverts. C'est faux, et faux d'une façon qui produit des réponses confiantes, plausibles, incorrectes. Tracer openat ne capture que les fichiers ouverts pendant la fenêtre de trace. Les vrais processus lisent à travers des descripteurs ouverts plus tôt, ou hérités d'un parent. Le service crée par fork des processus de travail qui héritent de descripteurs ouverts sur le stockage partagé. Donc le fichier qu'une trace openat n'a jamais vu, c'est exactement le fichier qui se fait marteler.

Pire, le processus qui apparaît dans ceph_readahead, c'est celui dont la lecture a déclenché le préchargement, qui n'est pas nécessairement celui qui a ouvert le fichier. Une minuscule lecture à travers un descripteur hérité tire 8 Mo, et le compte d'octets atterrit sur quiconque a émis cette lecture. L'attribution par openat seul aurait produit une histoire propre et fausse sur qui était responsable. Le compte d'octets ancré sur le compteur de confiance est correct quoi qu'il arrive; le qui, c'est la partie qui demande du soin.

Ce qu'était l'enquête#

Pas de patch au bout de celle-ci. La lecture anticipée de 8 Mo est sans doute correcte pour un système de fichiers conçu pour diffuser de gros objets; le bon correctif, c'est une conversation de réglage par montage, pas un changement de noyau, et cette conversation est maintenant quantifiée au lieu d'être une devinette. Le livrable, c'était l'explication: la charge de réception du réseau de stockage, ce sont des recherches de config par entité amplifiées d'environ 13x par la lecture anticipée, plus une tâche de migration qui disparaît au basculement, et voici la prédiction de ce qui arrive quand ça se produit.

L'explication n'était pas le bout difficile. Le bout difficile, c'était de refuser de livrer la lecture du piège de la cache, de refuser de livrer l'attribution par openat, et de refuser de faire confiance à mon propre profileur quand il était en désaccord avec un compteur que j'avais des raisons de croire. Ancrez-vous sur un chiffre qui ne peut pas mentir. Traitez l'attribution de processus et de chemin comme une hypothèse, pas comme la mesure. Séparez ce que l'application a demandé de ce que le cluster a livré. Quand votre instrument est en désaccord avec l'ancre, l'instrument a tort jusqu'à ce qu'il reproduise l'ancre par lui-même.

L'erreur de facteur 30 dans mon profileur, ce n'est pas le passage embarrassant de cette histoire. C'en est le point.