Problème mystérieux
Fin 2017, j'ai reçu un appel pour discuter d'un problème avec l'application Netflix sur le nouveau décodeur. Il s'agissait d'un nouvel Android TV compatible 4K basé sur la version 5.0 d'Android Open Source Project (AOSP), Lollipop. J'ai travaillé chez Netflix pendant plusieurs années et aidé à lancer quelques appareils, mais c'était mon premier Android TV.
Les quatre parties étaient en contact: une grande société européenne de télévision payante lançant l'appareil (opérateur), un intégrateur de micrologiciels (intégrateur), un fournisseur de système sur puce (fournisseur de puces) et moi-même (Netflix).
L'intégrateur et Netflix ont déjà terminé le processus de certification rigoureux de Netflix, mais lors d'un test interne avec l'opérateur, un dirigeant de l'entreprise a signalé un grave problème: la lecture de Netflix a été retardée, ce qui signifie que la vidéo a été lue pendant une très courte période, puis mise en pause, puis mise en pause, puis mise en pause. Cela ne s'est pas toujours produit, mais cela a commencé à ralentir régulièrement quelques jours après avoir allumé la console. Ils ont montré la vidéo, elle avait l'air terrible.
L'intégrateur a trouvé un moyen de reproduire le problème: lancer Netflix plusieurs fois, démarrer la lecture, puis revenir à l'interface utilisateur. Ils ont fourni un script pour automatiser le processus. Parfois, cela prenait jusqu'à cinq minutes, mais le script reproduisait toujours le bogue de manière fiable.
Pendant ce temps, un ingénieur d'un fournisseur de puces a diagnostiqué la cause première: une application Netflix Android TV appelée Ninja était incapable de fournir des données audio. Les retards sont causés par des sous-exécutions dans le pipeline audio matériel. La lecture s'est arrêtée lorsque le décodeur attendait une partie du flux audio du Ninja, puis a repris lorsque de nouvelles données sont arrivées. L'intégrateur, le fournisseur de puces et l'opérateur pensaient tous que le problème était clair. Et ils m'ont tous regardé: Netflix, vous avez un bug dans votre application et vous devez le corriger. J'ai entendu la tension dans la voix du représentant de l'opérateur. La sortie de l'appareil a été retardée et dépassait le budget, et ils attendaient des résultats de ma part.
Enquête
J'étais sceptique. Cette même application Ninja fonctionne sur des millions d'appareils Android TV, y compris les téléviseurs intelligents et autres décodeurs. S'il y a un bogue dans Ninja, pourquoi cela ne se produit-il que sur cet appareil?
J'ai commencé par répliquer moi-même le problème à l'aide d'un script de l'intégrateur. J'ai contacté un collègue du fabricant de puces et lui ai demandé s'il avait vu quelque chose comme ça (pas vu). Puis j'ai commencé à étudier le code source de Ninja. Il était nécessaire de trouver le code exact qui est responsable de la livraison des données audio. J'ai beaucoup compris, mais j'ai commencé à me perdre dans le code qui se charge de la reproduction, et j'avais besoin d'aide.
Je suis monté à l'étage et j'ai trouvé l'ingénieur qui a écrit le pipeline audio et vidéo Ninja, il m'a présenté le code. Ensuite, je l'ai moi-même étudié pendant un certain temps afin de comprendre enfin les parties principales et d'ajouter mes propres logs. L'application Netflix est complexe, mais sous une forme simplifiée, elle récupère les données du serveur Netflix, met en mémoire tampon les données vidéo et audio sur l'appareil pendant quelques secondes, puis délivre les images vidéo et audio une à la fois aux décodeurs matériels.
Figure: 1. Pipeline de lecture simplifié
Parlons un instant du pipeline audio / vidéo dans l'application Netflix. Avant la «mémoire tampon du décodeur», c'est exactement la même chose sur tous les décodeurs et téléviseurs, mais le déplacement des données A / V dans la mémoire tampon du décodeur d'un appareil est une procédure spécifique à l'appareil. Il fonctionne sur son propre fil. Le but de cette procédure est de garder la mémoire tampon du décodeur pleine en appelant la trame suivante de données audio ou vidéo via l'API Netflix. Dans Ninja, ce travail se fait par un filAndroid. Il existe une machine à états simple et une logique pour gérer les différents états de lecture, mais en lecture normale, le flux copie une image de données dans l'API de lecture Android, puis indique au planificateur de thread d'attendre 15 ms avant le prochain appel du gestionnaire. Lorsque vous créez un thread Android, vous pouvez demander au thread de redémarrer comme une boucle, mais c'est le planificateur de thread Android qui appelle le gestionnaire, pas votre propre application.
À 60 FPS maximum, l'appareil doit afficher une nouvelle trame toutes les 16,66 ms, donc vérifier après 15 ms suffit de toute façon. Puisque l'intégrateur a déterminé que le problème se situait dans le flux audio, je me suis concentré sur le gestionnaire spécifique qui livrait les échantillons audio au service audio Android.
Il fallait comprendre d'où viennent les retards, c'est-à-dire le retard. J'ai supposé qu'une fonction appelée par le gestionnaire était à blâmer, j'ai donc dispersé les messages de journal dans tout le gestionnaire et j'allais trouver facilement le code qui causait les décalages. Il est vite devenu clair qu'il n'y avait rien de mal avec le gestionnaire, et il a fonctionné pendant quelques millisecondes même lorsque la lecture était en retard.
Ouais, perspicacité
En fin de compte, je me suis concentré sur trois chiffres: le débit en bauds, le temps d'appel du gestionnaire et le temps de transfert du contrôle du gestionnaire vers Android. J'ai écrit un script pour analyser la sortie du journal et généré le graphique ci-dessous montrant la réponse. Figure: 2. Visualisation de la bande passante du streaming audio et des horaires du gestionnaire La ligne orange indique la vitesse à laquelle les données sont transférées du tampon de streaming vers le système audio Android (octets par milliseconde). Il existe trois scénarios différents dans ce diagramme:
- Deux zones avec des pics élevés, où les débits de données atteignent 500 octets par milliseconde. Cette phase est mise en mémoire tampon avant de démarrer la lecture. Le gestionnaire copie les données aussi vite que possible.
- — . 45 .
- , 10 . .
Conclusion inévitable: la ligne orange confirme les conclusions de l'ingénieur de la société de puces. En effet, Ninja n'est pas assez rapide pour fournir des données audio.
Pour comprendre pourquoi, regardons de plus près les lignes jaunes et grises.
La ligne jaune montre le temps passé dans la procédure du gestionnaire lui-même, calculé à partir des horodatages enregistrés au début et à la fin de la procédure. Dans les zones normales et en retard, le temps dans le gestionnaire est le même: environ 2 ms. Les rafales montrent des cas où les temps sont plus lents en raison d'autres tâches effectuées sur l'appareil.
La vraie cause fondamentale
La ligne grise - le temps entre les appels au gestionnaire - raconte une histoire différente. En lecture normale, le gestionnaire est appelé environ toutes les 15 ms. En cas de décalage à droite, le gestionnaire est appelé environ toutes les 55 ms. Il y a 40 ms supplémentaires entre les appels, et dans une telle situation, il ne peut pas suivre la lecture. Mais pourquoi?
J'ai signalé ma découverte à l'intégrateur et au fournisseur de puces (regardez, le planificateur de flux Android est à blâmer!), Mais ils ont continué à insister sur le fait que Netflix devrait résoudre le problème. Pourquoi ne pas copier plus de données chaque fois que le gestionnaire est appelé? C'était une critique juste, mais la mise en œuvre de ce comportement impliquerait des changements profonds auxquels je ne voulais pas, alors j'ai continué à rechercher la cause profonde. J'ai plongé dans le code source Android et j'ai découvert que les threads Android sont une construction d'espace utilisateur et que le planificateur de threads utilise un appel système pour se synchroniser
epoll()
. Je savais que les performances n'étaient
epoll()
pas garanties, alors je soupçonnais que quelque chose l'affectait systématiquement.
À ce stade, j'ai été sauvé par un autre ingénieur d'un fournisseur de puces qui a découvert un bogue déjà corrigé dans la prochaine version d'Android (Marshmallow). Il s'avère que le planificateur de threads Android modifie le comportement des threads selon que l'application s'exécute au premier plan ou en arrière-plan. Les threads d'arrière-plan se voient attribuer une latence supplémentaire de 40 ms (40 000 000 ns).
Un bogue profondément dans le cœur d'Android signifiait que cette valeur de minuterie supplémentaire persistait lorsque le fil était mis au premier plan. Habituellement, le thread du processeur audio était créé lorsque l'application était au premier plan, mais parfois un peu plus tôt lorsque le Ninja était encore en arrière-plan. Si cela se produisait, la lecture commencerait à ralentir.
Leçons apprises
Ce n'est pas le dernier bug que nous avons corrigé sur la plate-forme Android, mais c'était le plus difficile à localiser. C'était en dehors de l'application Netflix et même en dehors du pipeline de lecture, et toutes les données brutes indiquaient une erreur dans l'application Netflix elle-même.
L'histoire illustre un aspect de mon métier que j'aime: il est impossible de prévoir tous les problèmes que nos partenaires me poseront. Et je sais que pour les résoudre, il faut comprendre de nombreux systèmes, travailler avec d'excellents collègues et se pousser constamment à apprendre de nouvelles choses. Ce que je fais a un impact direct sur de vraies personnes et leur appréciation d'un excellent produit. Quand les gens aiment regarder Netflix dans leur salon, je sais que je fais partie de l'équipe qui a rendu cela possible.