Comment gérer: java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize () a expiré après 10 secondes d'erreurs?

Nous voyons un certain nombre de TimeoutExceptionsdans GcWatcher.finalize, BinderProxy.finalize, et PlainSocketImpl.finalize. Plus de 90% d'entre eux se produisent sur Android 4.3. Nous recevons des rapports à ce sujet de Crittercism des utilisateurs sur le terrain.

L'erreur est une variation de: " com.android.internal.BinderInternal$GcWatcher.finalize() timed out after 10 seconds"

java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize() timed out after 10 seconds
at android.os.BinderProxy.destroy(Native Method)
at android.os.BinderProxy.finalize(Binder.java:459)
at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:187)
at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:170)
at java.lang.Thread.run(Thread.java:841)

Jusqu'à présent, nous n'avons pas eu la chance de reproduire le problème en interne ou de déterminer ce qui aurait pu le causer.

Des idées sur ce qui peut causer cela? Une idée de comment déboguer cela et savoir quelle partie de l'application provoque cela? Tout ce qui éclaire le problème est utile.

Plus de Stacktraces:

1   android.os.BinderProxy.destroy  
2   android.os.BinderProxy.finalize Binder.java, line 482
3   java.lang.Daemons$FinalizerDaemon.doFinalize    Daemons.java, line 187
4   java.lang.Daemons$FinalizerDaemon.run   Daemons.java, line 170
5   java.lang.Thread.run    Thread.java, line 841  

2

1   java.lang.Object.wait   
2   java.lang.Object.wait   Object.java, line 401
3   java.lang.ref.ReferenceQueue.remove ReferenceQueue.java, line 102
4   java.lang.ref.ReferenceQueue.remove ReferenceQueue.java, line 73
5   java.lang.Daemons$FinalizerDaemon.run   Daemons.java, line 170
6   java.lang.Thread.run

3

1   java.util.HashMap.newKeyIterator    HashMap.java, line 907
2   java.util.HashMap$KeySet.iterator   HashMap.java, line 913
3   java.util.HashSet.iterator  HashSet.java, line 161
4   java.util.concurrent.ThreadPoolExecutor.interruptIdleWorkers    ThreadPoolExecutor.java, line 755
5   java.util.concurrent.ThreadPoolExecutor.interruptIdleWorkers    ThreadPoolExecutor.java, line 778
6   java.util.concurrent.ThreadPoolExecutor.shutdown    ThreadPoolExecutor.java, line 1357
7   java.util.concurrent.ThreadPoolExecutor.finalize    ThreadPoolExecutor.java, line 1443
8   java.lang.Daemons$FinalizerDaemon.doFinalize    Daemons.java, line 187
9   java.lang.Daemons$FinalizerDaemon.run   Daemons.java, line 170
10  java.lang.Thread.run

4

1   com.android.internal.os.BinderInternal$GcWatcher.finalize   BinderInternal.java, line 47
2   java.lang.Daemons$FinalizerDaemon.doFinalize    Daemons.java, line 187
3   java.lang.Daemons$FinalizerDaemon.run   Daemons.java, line 170
4   java.lang.Thread.run

Divulgation complète - Je suis l'auteur de la conférence mentionnée précédemment dans TLV DroidCon.

J'ai eu l'occasion d'examiner ce problème sur de nombreuses applications Android et d'en discuter avec d'autres développeurs qui l'ont rencontré - et nous sommes tous arrivés au même point: ce problème ne peut être évité, mais minimisé.

J'ai examiné de plus près l'implémentation par défaut du code Android Garbage Collector, pour mieux comprendre pourquoi cette exception est levée et quelles pourraient en être les causes possibles. J'ai même trouvé une cause fondamentale possible lors de l'expérimentation.

La racine du problème est au moment où un appareil «se met en veille» pendant un certain temps - cela signifie que le système d'exploitation a décidé de réduire la consommation de la batterie en arrêtant la plupart des processus User Land pendant un certain temps et en désactivant Screen, ce qui réduit les cycles du processeur , etc. La façon dont cela est fait - est au niveau du système Linux où les processus sont suspendus à mi-course. Cela peut se produire à tout moment pendant l'exécution normale de l'application, mais cela s'arrêtera à un appel système natif, car le changement de contexte est effectué au niveau du noyau. Alors - c'est là que le Dalvik GC rejoint l'histoire.

Le code du GC Dalvik (tel qu'implémenté dans le projet Dalvik sur le site AOSP) n'est pas un morceau de code compliqué. La façon dont cela fonctionne est décrite dans mes diapositives DroidCon. Ce que je n'ai pas couvert, c'est la boucle GC de base - au point où le collecteur a une liste d'objets à finaliser (et à détruire). La logique de boucle à la base peut être simplifiée comme ceci:

1. prendre starting_timestamp,
2. supprimer l'objet pour la liste des objets à libérer,
3. release object - finalize()et appelez native destroy()si nécessaire,
4. prendre end_timestamp,
5. calculer ( end_timestamp - starting_timestamp) et comparer avec une valeur de délai d'attente codée en dur de 10 secondes,
6. si le délai d'attente est atteint - lancez le java.util.concurrent.TimeoutExceptionet tuez le processus.

Considérez maintenant le scénario suivant:

L'application continue de faire son travail.

Ce n'est pas une application face à l'utilisateur, elle s'exécute en arrière-plan.

Au cours de cette opération en arrière-plan, des objets sont créés, utilisés et doivent être collectés pour libérer de la mémoire.

L'application ne dérange pas avec un WakeLock - car cela affectera la batterie de manière négative et semble inutile.

Cela signifie que l'application invoquera le GC de temps à autre.

Normalement, les courses GC sont effectuées sans accroc.

Parfois (très rarement) le système décide de s'endormir au milieu de l'analyse GC.

Cela se produira si vous exécutez votre application suffisamment longtemps et que vous surveillez de près les journaux de la mémoire Dalvik.

Maintenant, considérez la logique d'horodatage de la boucle GC de base, il est possible pour le périphérique de démarrer l'analyse, de prendre un start_stampet de s'endormir lors de l' destroy()appel natif sur un objet système.

Quand il se réveille et reprend la course, le destroy()se terminera, et le suivant end_stampsera le temps qu'il a pris l' destroy()appel + le temps de sommeil.

Si le temps de sommeil était long (plus de 10 secondes), le java.util.concurrent.TimeoutExceptionsera lancé.

J'ai vu cela dans les graphiques générés à partir du script python d'analyse - pour les applications système Android, pas seulement mes propres applications surveillées.

Collectez suffisamment de journaux et vous finirez par le voir.

Conclusion:

Le problème ne peut pas être évité - vous le rencontrerez si votre application s'exécute en arrière-plan.

Vous pouvez atténuer en prenant un WakeLock et empêcher l'appareil de dormir, mais c'est une histoire complètement différente, et un nouveau mal de tête, et peut-être un autre discours dans un autre con.

Vous pouvez minimiser le problème en réduisant les appels GC, ce qui rend le scénario moins probable (les conseils sont dans les diapositives).

Je n'ai pas encore eu la chance de passer en revue le code GC Dalvik 2 (alias ART) - qui dispose d'une nouvelle fonctionnalité de compactage générationnel, ni d'effectuer des expériences sur une sucette Android.

Ajouté le 05/07/2015:

Après avoir examiné l'agrégation des rapports de crash pour ce type de crash, il semble que ces plantages de la version 5.0+ du système d'exploitation Android (Lollipop avec ART) ne représentent que 0,5% de ce type de crash. Cela signifie que les modifications apportées à ART GC ont réduit la fréquence de ces plantages.

Ajouté le 1/6/2016:

On dirait que le projet Android a ajouté beaucoup d'informations sur le fonctionnement du GC dans Dalvik 2.0 (alias ART).

Vous pouvez en savoir plus ici - Débogage de ART Garbage Collection .

Il présente également certains outils permettant d'obtenir des informations sur le comportement du GC pour votre application.

L'envoi d'un SIGQUIT à votre processus d'application provoquera essentiellement un ANR et videra l'état de l'application dans un fichier journal pour analyse.

Nous voyons cela constamment, partout dans notre application, en utilisant Crashlytics. Le crash se produit généralement dans le code de la plate-forme. Un petit échantillon:

android.database.CursorWindow.finalize () a expiré après 10 secondes

java.util.regex.Matcher.finalize () a expiré après 10 secondes

android.graphics.Bitmap $ BitmapFinalizer.finalize () a expiré après 10 secondes

org.apache.http.impl.conn.SingleClientConnManager.finalize () a expiré après 10 secondes

java.util.concurrent.ThreadPoolExecutor.finalize () a expiré après 10 secondes

android.os.BinderProxy.finalize () a expiré après 10 secondes

android.graphics.Path.finalize () a expiré après 10 secondes

Les appareils sur lesquels cela se produit sont majoritairement (mais pas exclusivement) des appareils fabriqués par Samsung. Cela pourrait simplement signifier que la plupart de nos utilisateurs utilisent des appareils Samsung; cela pourrait également indiquer un problème avec les appareils Samsung. Je ne suis pas vraiment sûr.

Je suppose que cela ne répond pas vraiment à vos questions, mais je voulais simplement souligner que cela semble assez courant et n'est pas spécifique à votre application.

J'ai trouvé des diapositives sur ce problème.

http://de.slideshare.net/DroidConTLV/android-crash-analysis-and-the-dalvik-garbage-collector-tools-and-tips

Dans cette diapositive, l'auteur dit que cela semble être un problème avec GC, s'il y a beaucoup d'objets ou d'énormes objets dans le tas. La diapositive comprend également une référence à un exemple d'application et un script python pour analyser ce problème.

https://github.com/oba2cat3/GCTest

https://github.com/oba2cat3/logcat2memorygraph

De plus, j'ai trouvé un indice dans le commentaire n ° 3 de ce côté: https://code.google.com/p/android/issues/detail?id=53418#c3

Nous avons résolu le problème en arrêtant le FinalizerWatchdogDaemon.

public static void fix() {
    try {
        Class clazz = Class.forName("java.lang.Daemons$FinalizerWatchdogDaemon");

        Method method = clazz.getSuperclass().getDeclaredMethod("stop");
        method.setAccessible(true);

        Field field = clazz.getDeclaredField("INSTANCE");
        field.setAccessible(true);

        method.invoke(field.get(null));

    }
    catch (Throwable e) {
        e.printStackTrace();
    }
}

Vous pouvez appeler la méthode dans le cycle de vie de l'application, comme attachBaseContext(). Pour la même raison, vous pouvez également spécifier la fabrication du téléphone pour résoudre le problème, c'est à vous de décider.

Délai d'expiration des récepteurs de diffusion après 10 secondes. Peut-être que vous faites un appel asynchrone (faux) à partir d'un récepteur de diffusion et que 4.3 le détecte réellement.

Voici une solution efficace de didi pour résoudre ce problème, puisque ce bogue est très courant et difficile à trouver la cause, il ressemble plus à un problème système, pourquoi ne pouvons-nous pas l'ignorer directement？ Bien sûr, nous pouvons l'ignorer, ici est l'exemple de code:

final Thread.UncaughtExceptionHandler defaultUncaughtExceptionHandler = 
        Thread.getDefaultUncaughtExceptionHandler();
Thread.setDefaultUncaughtExceptionHandler(new Thread.UncaughtExceptionHandler() {
    @Override
    public void uncaughtException(Thread t, Throwable e) {
        if (t.getName().equals("FinalizerWatchdogDaemon") && e instanceof TimeoutException) {
        } else {
            defaultUncaughtExceptionHandler.uncaughtException(t, e);
        }
    }
});

En définissant un gestionnaire d'exceptions non interceptées par défaut spécial, l'application peut changer la façon dont les exceptions non interceptées sont gérées pour les threads qui accepteraient déjà le comportement par défaut fourni par le système. Quand un uncaught TimeoutExceptionest jeté à partir d'un thread nommé FinalizerWatchdogDaemon, ce gestionnaire spécial bloquera la chaîne de gestionnaires, le gestionnaire système ne sera pas appelé, donc un crash sera évité.

Grâce à la pratique, aucun autre mauvais effet n'a été trouvé. Le système GC fonctionne toujours, les délais d'attente sont atténués lorsque l'utilisation du processeur diminue.

Pour plus de détails, voir: https://mp.weixin.qq.com/s/uFcFYO2GtWWiblotem2bGg

Une chose qui est invariablement vraie est qu'à ce moment, l'appareil suffoquerait pour une certaine mémoire (ce qui est généralement la raison pour laquelle GC se déclenche très probablement).

Comme mentionné précédemment par presque tous les auteurs, ce problème survient lorsque Android tente d'exécuter GC alors que l'application est en arrière-plan. Dans la plupart des cas où nous l'avons observé, l'utilisateur a mis l'application en pause en verrouillant son écran. Cela peut également indiquer une fuite de mémoire quelque part dans l'application ou que le périphérique est déjà trop chargé. Le seul moyen légitime de le minimiser est donc:

• pour s'assurer qu'il n'y a pas de fuite de mémoire, et
• pour réduire l'empreinte mémoire de l'application en général.

try {
    Class<?> c = Class.forName("java.lang.Daemons");
    Field maxField = c.getDeclaredField("MAX_FINALIZE_NANOS");
    maxField.setAccessible(true);
    maxField.set(null, Long.MAX_VALUE);
} catch (ClassNotFoundException e) {
    e.printStackTrace();
} catch (NoSuchFieldException e) {
    e.printStackTrace();
} catch (IllegalAccessException e) {
    e.printStackTrace();
}

Le finalizeQueue est peut-être trop long

je pense que java peut nécessiter GC.SuppressFinalize () & GC.ReRegisterForFinalize () pour permettre à l'utilisateur de réduire explicitement la longueur de la file d' attente finalisée

si le code source de la JVM est disponible, peut implémenter ces méthodes nous-mêmes, comme le fabricant de ROM Android

Cela ressemble à un bogue Android Runtime. Il semble y avoir un finaliseur qui s'exécute dans son thread séparé et appelle la méthode finalize () sur les objets s'ils ne sont pas dans le cadre actuel du stacktrace. Par exemple, le code suivant (créé pour vérifier ce problème) s'est terminé par le plantage.

Prenons un curseur qui fait quelque chose dans la méthode finalize (par exemple ceux de SqlCipher, faites close () qui verrouille la base de données actuellement utilisée)

private static class MyCur extends MatrixCursor {


    public MyCur(String[] columnNames) {
        super(columnNames);
    }

    @Override
    protected void finalize() {
        super.finalize();

        try {
            for (int i = 0; i < 1000; i++)
                Thread.sleep(30);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

Et nous faisons des trucs longs après avoir ouvert le curseur:

for (int i = 0; i < 7; i++) {
        new Thread(new Runnable() {
            @Override
            public void run() {
                MyCur cur = null;
                try {
                    cur = new MyCur(new String[]{});
                    longRun();
                } finally {
                    cur.close();
                }
            }

            private void longRun() {
                try {
                    for (int i = 0; i < 1000; i++)
                        Thread.sleep(30);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }).start();
    }

Cela provoque l'erreur suivante:

FATAL EXCEPTION: FinalizerWatchdogDaemon
                                                                        Process: la.la.land, PID: 29206
                                                                        java.util.concurrent.TimeoutException: MyCur.finalize() timed out after 10 seconds
                                                                            at java.lang.Thread.sleep(Native Method)
                                                                            at java.lang.Thread.sleep(Thread.java:371)
                                                                            at java.lang.Thread.sleep(Thread.java:313)
                                                                            at MyCur.finalize(MessageList.java:1791)
                                                                            at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:222)
                                                                            at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:209)
                                                                            at java.lang.Thread.run(Thread.java:762)

La variante de production avec SqlCipher est très similaire:

12-21 15:40:31.668: E/EH(32131): android.content.ContentResolver$CursorWrapperInner.finalize() timed out after 10 seconds
12-21 15:40:31.668: E/EH(32131): java.util.concurrent.TimeoutException: android.content.ContentResolver$CursorWrapperInner.finalize() timed out after 10 seconds
12-21 15:40:31.668: E/EH(32131): 	at java.lang.Object.wait(Native Method)
12-21 15:40:31.668: E/EH(32131): 	at java.lang.Thread.parkFor$(Thread.java:2128)
12-21 15:40:31.668: E/EH(32131): 	at sun.misc.Unsafe.park(Unsafe.java:325)
12-21 15:40:31.668: E/EH(32131): 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:161)
12-21 15:40:31.668: E/EH(32131): 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:840)
12-21 15:40:31.668: E/EH(32131): 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:873)
12-21 15:40:31.668: E/EH(32131): 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
12-21 15:40:31.668: E/EH(32131): 	at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
12-21 15:40:31.668: E/EH(32131): 	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
12-21 15:40:31.668: E/EH(32131): 	at net.sqlcipher.database.SQLiteDatabase.lock(SourceFile:518)
12-21 15:40:31.668: E/EH(32131): 	at net.sqlcipher.database.SQLiteProgram.close(SourceFile:294)
12-21 15:40:31.668: E/EH(32131): 	at net.sqlcipher.database.SQLiteQuery.close(SourceFile:136)
12-21 15:40:31.668: E/EH(32131): 	at net.sqlcipher.database.SQLiteCursor.close(SourceFile:510)
12-21 15:40:31.668: E/EH(32131): 	at android.database.CursorWrapper.close(CursorWrapper.java:50)
12-21 15:40:31.668: E/EH(32131): 	at android.database.CursorWrapper.close(CursorWrapper.java:50)
12-21 15:40:31.668: E/EH(32131): 	at android.content.ContentResolver$CursorWrapperInner.close(ContentResolver.java:2746)
12-21 15:40:31.668: E/EH(32131): 	at android.content.ContentResolver$CursorWrapperInner.finalize(ContentResolver.java:2757)
12-21 15:40:31.668: E/EH(32131): 	at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:222)
12-21 15:40:31.668: E/EH(32131): 	at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:209)
12-21 15:40:31.668: E/EH(32131): 	at java.lang.Thread.run(Thread.java:762)

Reprendre: fermez les curseurs dès que possible. Au moins sur Samsung S8 avec Android 7 où le problème a été constaté.

Pour les classes que vous créez (c'est-à-dire qui ne font pas partie d'Android), il est possible d'éviter complètement le crash.

Toute classe qui implémente finalize()a une probabilité inévitable de planter comme expliqué par @oba. Donc, au lieu d'utiliser des finaliseurs pour effectuer le nettoyage, utilisez un fichier PhantomReferenceQueue.

Pour un exemple, consultez l'implémentation dans React Native: https://github.com/facebook/react-native/blob/master/ReactAndroid/src/main/java/com/facebook/jni/DestructorThread.java