AsyncLocal et ExecutionContext

Dans ce court article, je décris un problème que j’ai trouvé intéressant. Cela concerne ce qu’il me semble être un défaut de design de .NET avec AsyncLocal et ExecutionContext. On pourrait même simplifier en ne parlant que de AsyncLocal car je vois l’existence de ExecutionContext comme une conséquence pour supporter le premier.

Je pense que l’on va rencontrer ce « défaut » de plus en plus souvent sur un framework tel que ASP.NET Core à cause de deux choses:

La recrudescence de frameworks qui s’appuient sur AsyncLocal.
ASP.NET Core qui par conception favorise l’activation « juste à temps » (lazy) de services (par exemple démarrer une tâche d’arrière-plan la première fois que celle-ci est nécessaire, c’est-à-dire suite à la réception d’une requête).

Problème constaté

Voir le code source suivant sur Github: https://github.com/eric-b/Samples/AsyncLocal-ExecutionContext/Demo (le lien pointe un commit particulier).

Pour cette demo, je suis simplement parti d’un modèle de code standard ASP.NET Core Web Application inclus dans Visual Studio 2019. Il contient un seul contrôleur avec une fausse API de prévisions météo (WeatherForecastController).

J’ai modifié le code de façon à ce que le contrôleur fasse appel à un composant tiers pour obtenir les prévisions (WeatherForecastService.cs). Ce composant expose une méthode publique pour obtenir les prévisions. La première fois qu’il est appelé, ce composant:

Simule une requête à une API tierce pour obtenir les prévisions (l’appel est simulé avec une latence aléatoire entre 500ms et 3 secondes, les résultats sont simplement des valeurs aléatoires comme dans le code original du modèle inclus dans Visual Studio).
Et démarre un timer qui va rafraichir ces prévisions toutes les 10 secondes, de façon à ce que les prochains appels retournent un résultat immédiatement sans latence.

Si vous lancez le programme et que vous appelez l’API deux fois avec un court écart entre les deux appels (Swagger UI est intégré), vous constaterez que la réponse est différente à chaque appel et qu’elle n’est pas immédiate. Environ 15 secondes après le premier appel, si vous rappelez plusieurs fois l’API, on constate que la réponse est immédiate et ne varie plus systématiquement entre chaque appel. C’est parce que le timer est entré en fonction pour rafraichir les résultats à intervalles réguliers.

Bien que le code de cette demo ne soit absolument pas un bon modèle pour une vraie application, il montre j’espère quelque chose d’assez proche de ce que l’on peut vouloir faire, avec un code assez minimal.

Il n’y a rien d’anormal à constater a priori dans cette demo.

Le « bug » se manifeste quand on utilise le nouveau framework OpenTelemetry, basé sur Activity (et sur ActivitySource). Avec le recul que j’ai maintenant, on peut anticiper qu’il peut y avoir un souci en lisant la documentation de cette classe qui parle de la présence d’un propriété statique Activity.Current. On peut donc se douter qu’en interne AsyncLocal est utilisé.

Pour l’observer, il suffit de regarder les traces collectées. Dans cet exemple, j’exporte les traces OpenTelemetry vers Jaeger. Pour lancer Jaeger en local sur docker (commande issue de la documentation Jaeger):

$ docker run -d --name jaeger \
  -e COLLECTOR_ZIPKIN_HOST_PORT=:9411 \
  -p 5775:5775/udp \
  -p 6831:6831/udp \
  -p 6832:6832/udp \
  -p 5778:5778 \
  -p 16686:16686 \
  -p 14268:14268 \
  -p 14250:14250 \
  -p 9411:9411 \
  jaegertracing/all-in-one:1.22

Jaeger UI sera accessible sur http://localhost:16686

Si on relance l’application et que l’on refait le même test pour que les traces soient exportées vers Jaeger, et qu’on les visualise sur son UI, on constate qu’il y a un problème:

Capture d’écran

Sur la capture précédente, on voit une trace censée représenter un seul appel à l’API: WeatherForecast appelé (représente la requête reçue par notre API), get_weather_forecast_from_controller représente le traitement au sein de notre contrôleur WeatherForecastController. On voit que celui-ci a fait appel à notre service météo WeatherForecastService (get_forecast_from_service), et que notre service météo a traité la demande en faisant une requête à un service distant request_actual_forecast.

Ce qui ne va pas, c’est que l’on voit aussi une succession de traces liées à notre tâche d’arrière-plan (via un Timer): async_timer_refresh_forecast -> request_actual_forecast. Tant que l’application n’est pas interrompue, la trace générée par notre première requête au contrôleur va s’enrichir des traces générées par le timer. Dans la capture d’écran, on voit que notre requête aurait duré 1 minute et 6 secondes alors qu’elle n’a duré en réalité que 2,57 secondes. La durée de 1 minute correspond simplement à la durée de vie de l’application au moment où on visualise cette trace.

Le problème est qu’évidemment, on souhaite voir ces traces en dehors du contexte d’une requête du contrôleur. On devrait voir une nouvelle trace indépendante toutes les 10 secondes, concernant la mise à jour des prévisions météo, indépendamment des requêtes reçues par notre API.

Pourquoi le timer hérite-t-il du contexte de la requête entrante ?

Le problème est dû au fait que la requête qu’on fait via SwaggerUI va déclencher l’instanciation de WeatherForecastController. Celui-ci dépend de notre service WeatherForecastService inscrit en tant que singleton (dans IServiceCollection). Comme ce service n’est pas créé au démarrage de l’application mais seulement la première fois qu’il est requis, c’est-à-dire quand une requête au contrôleur a été reçue, le Timer qu’il crée se voit hériter d’un ExecutionContext lié à la requête entrante. Comme l’implémentation de OpenTelemetry en .NET s’appuie sur Activity.Current pour la relation entre traces parent et traces enfant, et que cette propriété utilise AsyncLocal, cela explique (j’espère) que les traces générées dans le callback du timer sur un background thread héritent du contexte du thread de la requête au contrôleur, qui n’a rien à voir en fait avec le traitement du timer. Si on avait forcé l’instanciation de WeatherForecastService au démarrage de l’application, on n’observerait pas ce problème.

Un rappel plus bas sur ce que sont AsyncLocal et ExecutionContext, avec un lien vers des articles détaillés, sera peut-être plus évocateur sur les mécanismes en jeu en interne.

Solution

La solution dans notre demo est d’empêcher que ExecutionContext soit propagé au background thread du timer.

Le problème est bien connu de Microsoft (cf. Proposal: Timer static Create methods that make rooting behavior explicit #27654). Ce qu’on peut regretter est qu’il n’est pas vraiment documenté (sauf à considérer les issues de Github comme de la doc).

La solution actuelle est une classe helper malheureusement interne, que l’on trouve ici: https://github.com/dotnet/aspnetcore/src/Shared/NonCapturingTimer (comme elle est interne, on en retrouve une copie dans d’autres frameworks, un exemple sur le projet Orleans).

La correction dans notre application est sur cette ligne.

Si on relance notre demo, on observe le résultat attendu. A savoir des traces indépendantes pour les requêtes reçues par l’application (WeatherForecast) et le timer de la tâche de fond (async_timer_refresh_forecast).

Capture d’écran

Petit rappel sur chaque élément

Tout développeur qui lira cet article saura sans aucun doute ce qu’est System.Threading.Timer. Pour AsyncLocal et ExecutionContext, ils sont peut-être familiers mais « de plus loin » puisqu’on a rarement à faire à eux directement.

AsyncLocal

AsyncLocal sert à déclarer dans le code qu’une variable est locale à un contrôle de flux asynchrone, tel qu’une méthode asynchrone (avec async/await).

Cette phrase est une traduction littérale du commentaire de code sur la classe AsyncLocal<T>.

C’est grosso-modo (mais pas exactement) similaire au concept de ThreadLocalStorage (TLS) adapté au nouveau modèle de programmation asynchrone avec async/await. Là où TLS permet de partager une variable (statique) par thread, AsyncLocal permet de partager une variable (toujours statique) par chaîne d’appel asynchrone (typiquement de la méthode A qui appelle de manière asynchrone la méthode B – qui s’exécute donc éventuellement sur un autre thread).

ExecutionContext

ExecutionContext est le conteneur qui sert à propager les valeurs AsyncLocal dans la chaîne d’appels asynchrones. À chaque fois que await est utilisé, le contexte du thread courant est copié, et il est restauré sur le thread qui exécute le code asynchrone (si celui-ci s’exécute effectivement sur un autre thread, ce qui n’est pas une garantie).

A noter: comme le rappelle cette FAQ sur ConfigureAwait, la méthode ConfigureAwait(false) n’a aucun effet sur la propagation de ExecutionContext (il est toujours propagé). ConfigureAwait(false) sert à modifier le comportement relatif à SynchronizationContext qui est un concept différent (mais bien lié à ExecutionContext). Le même auteur de cette FAQ propose un article beaucoup plus détaillé et devenu une référence à propos de ExecutionContext et SynchronizationContext.

Pourquoi appeler cela un défaut de design ?

Premièrement pourquoi ne pas appeler cela un bug dans le framework .NET ? Le problème original n’est certainement pas un bug car pris un par un, chaque élément (AsyncLocal, ExecutionContext, Timer) se comporte comme prévu. Le problème apparait lorsqu’on réunit tous ces éléments. D’ailleurs, le problème décrit ici peut tout à fait se produire sans Timer. Par exemple une tâche de fond, longue durée, lancée avec Task.Run. Un cas que je trouve typique est de lancer un background thread pour dépiler une file telle que ConcurrentQueue<T>. Supposons que cette file soit alimentée par le thread d’une requête traitée par un contrôleur, et qu’elle soit dépilée par un background thread démarré de manière latente, lorsqu’on y a mis un premier élément à traiter. Le même problème qu’avec le timer va se produire. Donc même si .NET s’enrichit d’un nouveau type de timer (ce qui est en gestation, cf. API proposal: Modern Timer API #31525), cela ne va pas éliminer le défaut décrit ici (ça le rendra juste moins récurrent, ce qui est déjà bien).

Deuxièmement, pourquoi parler de défaut de design dans .NET, et non d’une mauvaise utilisation (incriminant le développeur plutôt que Microsoft) ? C’est sûrement discutable, on peut toujours reprocher au développeur de ne pas assez bien connaître ses outils et de mal les utiliser. Pour éviter de m’étendre en explications et justifications là dessus, je me contenterai de pointer vers l’utilisation répétée de ce « hack » qu’est actuellement NonCapturingTimer dans le framework ASP.NET Core et dans d’autres frameworks de Microsoft. Tant que cette classe ou un helper équivalent ne sera pas proposé de manière standard (inclus dans le framework), il me semble difficile de ne pas reconnaître que c’est bien un défaut de conception, puisqu’il faut recourir à ce code très inhabituel et pas franchement intuitif pour corriger certaines situations qui, elles, n’ont rien de très inhabituelles. Comme deuxième argument, je note qu’actuellement ni la documentation de Timer ou de Task.Run n’avertit sur une possible mauvaise utilisation liée à la façon dont AsyncLocal peut incorrectement se propager sur un background thread (ni la documentation sur le « Modèle de programmation asynchrone des tâches »). Donc à part constater le problème par sa propre expérience (ou celle de collègues), il me paraît difficile de l’anticiper.

Une autre difficulté liée à AsyncLocal est qu’il s’agit généralement d’un « détail d’implémentation », pas visible du développeur qui utilise un framework. A mon avis, il faudrait que tout composant basé sur AsyncLocal le spécifie de façon claire dans sa documentation, exactement comme on indiquerait si un composant est thread safe ou non (car on ne peut pas l’utiliser de la même manière, sans quelques mauvaises surprises). Cela permettrait a minima de mieux anticiper le défaut décrit ici. Sans cela, il faut soit étudier le code source du framework qu’on utilise, soit attendre de constater des bugs dans son application. C’est une illustration du model-code gap, l’écart entre le code source et son modèle conceptuel, autrement dit, le code n’exprime pas tout (j’ai écrit un article sur le sujet il y a 5 ans). Mon point de vue est que plus cet écart est grand (entre le code source et la représentation mentale que l’on se fait de son fonctionnement), moins son design est bon. Il y a tout un tas de justifications légitimes à cela cependant, telle que privilégier les performances plutôt que la maintenabilité du code (en l’occurrence, cette justification ne s’applique pas au sujet de cet article).

Eric Boumendil