MISE À JOUR avec de nouvelles informations importantes (voir en bas)
ÉDITÉ avec un meilleur code de journalisation
Je traque une corruption graphique dans notre application, et je l'ai retracée à cette fonction (que j'ai généreusement saupoudré de journalisation):
09-30 15:56:37.686 1815-2373/? I/[Monkey]: M_E BEFORE: 2.0 1.0 3.0 4.0 5.0 1.0 09-30 15:56:37.687 1815-2373/? I/zygote64: Deoptimizing int app.hidden.name.c_IffLT.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:56:37.687 1815-2373/? I/zygote64: Deoptimizing int app.hidden.name.c_Delay.p_Pump2(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:56:37.687 1815-2373/? I/zygote64: Deoptimizing int app.hidden.name.c_SetUniform_4F.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:56:37.687 1815-2373/? I/zygote64: Deoptimizing int app.hidden.name.c_EX_VarString.p_Set7(app.hidden.name.c_Expression) due to JIT inline cache 09-30 15:56:37.688 1815-2373/? I/zygote64: Deoptimizing java.lang.String app.hidden.name.c_EX_Format.p_AsString() due to JIT inline cache 09-30 15:56:37.688 1815-2373/? I/zygote64: Deoptimizing int app.hidden.name.c_IffNotEqual.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:56:37.688 1815-2373/? I/zygote64: Deoptimizing int app.hidden.name.c_PinVP.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:56:37.688 1815-2373/? I/[Monkey]: M_E AFTER: 2.0 -5.6063644E-30 3.0 4.0 5.0 -5.6063644E-30
La plupart du temps, cela fonctionne comme prévu, mais à un certain moment du jeu, cela est enregistré:
09-30 15:20:51.219 28384-28877/? I/[Monkey]: M_E ETC BEFORE: 1.0 1.0 1.0 1.0 1.0 1.0 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing int app.hidden.name.c_IffLT.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing int app.hidden.name.c_Delay.p_Pump2(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing int app.hidden.name.c_SetUniform_4F.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing int app.hidden.name.c_EX_VarString.p_Set7(app.hidden.name.c_Expression) due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing java.lang.String app.hidden.name.c_EX_Format.p_AsString() due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing int app.hidden.name.c_IffNotEqual.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/zygote64: Deoptimizing int app.hidden.name.c_PinVP.p_Update4(app.hidden.name.c_Gel) due to JIT inline cache 09-30 15:20:51.220 28384-28877/? I/[Monkey]: M_E ETC AFTER: 6.7E-44 6.7E-44 6.7E-44 6.7E-44 6.7E-44 6.7E-44
Pour décomposer cela pour vous: une valeur statique m_dissolve est copiée dans une variable locale t_d et a la valeur 1.0f. La valeur statique est ensuite modifiée à 0,1f et utilisée dans le rendu des objets enfants. Une fois cette opération terminée, la variable locale t_d est à nouveau enregistrée avant d'être utilisée pour rétablir la valeur statique, mais elle est mystérieusement devenue -1,6314132E-19 entre-temps (cette valeur semble à chaque fois différente de manière imprévisible) .
Je n'ai connaissance d'aucune manière qu'une variable Java locale pourrait être corrompue de cette manière.
MISE À JOUR:
Comme test, j'ai fait de t_d une variable membre de la classe contenant la liste de code ci-dessus (plutôt qu'une variable locale), et sa valeur n'était plus corrompue.
Comme test supplémentaire, j'ai ensuite ajouté un flottant local variables (m_e à m_j) qui n'ont servi à rien sauf à imprimer avant et après super.p_PostDraw (). Voici ce qui s'est passé:
09-30 15:20:51.219 28384-28877/? I/[Monkey]: M_E ETC BEFORE: 1.0 1.0 1.0 1.0 1.0 1.0 09-30 15:20:51.220 28384-28877/? I/[Monkey]: M_E ETC AFTER: 6.7E-44 6.7E-44 6.7E-44 6.7E-44 6.7E-44 6.7E-44
J'ai ensuite supprimé tous les filtres du logcat et j'ai trouvé ceci caché entre ces deux lignes:
09-30 14:40:59.086 10545-11101/? I/[Monkey]: Dissolve encountered. 09-30 14:40:59.086 10545-11101/? I/[Monkey]: Cached dissolve value locally: 1.0 1.0 09-30 14:40:59.086 10545-11101/? I/[Monkey]: Updated dissolve value: 0.1 09-30 14:40:59.086 10545-11101/? I/[Monkey]: Monitoring t_d=1.0 09-30 14:40:59.087 10545-11101/? I/[Monkey]: Monitoring t_d=-1.6314132E-19 09-30 14:40:59.087 10545-11101/? I/[Monkey]: Dissolve post restore -1.6314132E-19MISE À JOUR:
J'ai modifié le code ci-dessus pour définir les variables locales sur des valeurs différentes plutôt que sur 1.0f, et ceci s'est produit:
public final int p_PostDraw(){
bb_std_lang.print("Dissolve encountered.");
float t_d=c_GColour.m_dissolve;
bb_std_lang.print("Cached dissolve value locally: "+c_GColour.m_dissolve+ " " + t_d);
c_GColour.m_dissolve=c_Gel.m_colstack.p_Top().m_a;
bb_std_lang.print("Updated dissolve value: " + c_GColour.m_dissolve);
c_Gel.m_colstack.p_Top().m_a=1.0f;
bb_std_lang.print("Monitoring t_d="+t_d);
super.p_PostDraw();
bb_std_lang.print("Monitoring t_d="+t_d);
c_GColour.m_dissolve=t_d;
bb_std_lang.print("Dissolve post restore " + c_GColour.m_dissolve);
return 0;
}
En d'autres termes, seule la variable locale définie sur 1.0f était corrompue. Pas le premier déclaré ou quoi que ce soit, JUSTE celui défini à 1.0f. J'ai ensuite essayé de définir toutes les variables locales sur des nombres différents AUTRES que 1.0f et aucune corruption ne s'est produite .
Il doit sûrement y avoir une sorte de récompense pour le bogue le plus obscur? Qu'une variable locale sera corrompue si l'ART désoptimise les fonctions, mais seulement si cette variable locale a la valeur 1.0?
3 Réponses :
Je ne suis au courant d'aucune manière qu'une variable Java locale pourrait être corrompue de cette manière.
Cela peut arriver si un code natif quelque part piétine le cadre de pile contenant la variable
t_d.Cela peut également se produire s'il y a une condition de concurrence ou un risque de mémoire dans cette section:
float t_d=c_GColour.m_dissolve; bb_std_lang.print("Dissolve pre stack: " + c_GColour.m_dissolve);Si vous regardez attentivement, vous n'imprimez pas réellement
t_d. Ce que vous faites, c'est imprimer la valeur (apparente) dec_GColour.m_dissolve... après qu'elle a été affectée àt_d. Cela a peut-être changé.(Notez que vous accédez à une variable nue
m_dissolve, apparemment sans aucune synchronisation. Il y a une condition de concurrence potentielle ici même sim_disolve code> est déclaré commevolatile.)
Merci - J'ai eu une version où j'ai imprimé t_d mais je ne l'ai pas incluse dans l'OP. Je modifie maintenant. De plus, un seul thread accède à m_dissolve.
OK, donc mon argent est maintenant sur un problème avec le code natif ou peut-être une mauvaise utilisation de Unsafe .
J'ai jeté ensemble d'autres tests et supprimé tous les filtres de logcat. Cela change-t-il la destination de votre argent?
Ouais. Cela peut être une erreur matérielle ou un bogue du compilateur. Mais vous n'avez pas mentionné qu'il s'agissait d'Android plutôt que de Java ... et cela pourrait aussi faire une différence.
claque le front Merci; J'ai parcouru environ cinq titres différents pour cela et j'ai réussi à perdre «Android» sur celui pour lequel je me suis installé.
C'est un problème vraiment étrange et il semble que ce soit un bogue dans ART / JIT. Je peux voir au moins 3 histoires de développeurs différentes avec le même problème. Je pense qu'il pourrait y en avoir beaucoup plus mais ce bug est vraiment difficile à reproduire.
J'ai rencontré ce problème lors du développement du jeu en utilisant le framework LibGDX. L'interface utilisateur dans ce cadre est créée avec de nombreux calculs complexes et les flottants y sont intensivement utilisés. Dans mon cas, les composants de l'interface utilisateur ont reçu des coordonnées erronées, la mise en page était donc complètement cassée.
Chose étrange, vous ne pouvez pas reproduire ce problème avec DEBUG apk, uniquement avec RELEASE apk. La modification de la valeur du manifeste android: debuggable = true ne fonctionnera pas non plus. Le débogage est donc vraiment pénible, vous devez surveiller logcat et vérifier les valeurs des variables flottantes.
Il y a un problème qui a été créé par @Peeling, donc si vous avez un problème lié, veuillez demander aux développeurs Android de le résoudre: https://issuetracker.google.com/issues/141825192
J'ai forcé le compilateur à effectuer une "désoptimisation" des méthodes liées à l'interface utilisateur avant que j'en ai réellement besoin. J'ai créé un composant simulé "Table", je l'ai rempli avec d'autres composants simulés (créant une mise en page similaire à la vraie) et j'ai appelé les méthodes que j'ai pu voir dans les journaux (lorsque la désoptimisation se produisait). J'effectue cette opération à chaque fois au démarrage de l'application et le problème semble être "corrigé" pour moi - "La désoptimisation" ne se produit jamais après ce point et la mise en page est toujours correcte après cela.
J'espère que cela aidera quelqu'un qui a également passé beaucoup de temps sur ce problème.
J'ai également rencontré ce problème dans mon jeu sorti avec LibGDX, tout comme tscissors.
Après plusieurs mois de débogage, je suis maintenant sûr que les problèmes que j'ai rencontrés étaient liés à des variables flottantes détruites, comme décrit dans cet article.
Pour moi, une solution de contournement simple m'a aidé: dans AndroidManifest.xml , la définition de l'attribut android: vmSafeMode sur true a éliminé le bogue avec succès, car il désactive les optimisations JIT.
Voir la description d'Android:
android:vmSafeMode
Indique si l'application souhaite que la machine virtuelle (VM) fonctionne en mode sans échec. La valeur par défaut est "false". Cet attribut a été ajouté au niveau de l'API 8 où la valeur "true" a désactivé le compilateur juste-à-temps (JIT) de Dalvik.
Cet attribut a été adapté au niveau de l'API 22 où la valeur "true" a désactivé le compilateur ART en avance (AOT).
Cela peut affecter les performances de l'application. Avez-vous remarqué des changements dans les performances après avoir ajouté cette valeur? J'ai également essayé cette option, mais après avoir lu quelques avertissements et en raison du manque de documentation officielle, j'ai décidé de chercher une autre solution.
Oui, l'aspect performance est un point important et finalement c'est un compromis entre le risque de bugs de mise en page (ou potentiellement d'autres comportements étranges) et les problèmes de performances. Dans mon cas, seul le temps pendant lequel mes IA calculent est sensiblement augmenté et le rendu est toujours bon à près de 60 FPS. Je peux dormir beaucoup mieux avec le temps de calcul un peu pire des IA qu'avec la peur que les mises en page soient brisées arbitrairement. :-)
Dans quel environnement cela fonctionne-t-il? Y a-t-il un code JNI / JNA impliqué?
Peut-être que
t_détait6.7E-44depuis le début: il n'est pas imprimé avant lapré-restauration.Désolé, j'ai vérifié mais je ne l'ai pas inclus dans le PO. Va modifier.
D'accord, j'ai modifié l'OP afin que t_d soit surveillé tout au long, et vous pouvez voir qu'il est corrompu quelque part dans super.p_PostDraw ()
Nous avons également ce bug maintenant. Il était très difficile de trouver le problème, merci pour la question ici. Avez-vous une mise à jour pour le problème @Peeling?