usage - release resources android




Come gestire: java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize() scaduto dopo 10 secondi di errore? (6)

Stiamo vedendo un numero di TimeoutExceptions in GcWatcher.finalize, BinderProxy.finalize e PlainSocketImpl.finalize . Il 90% di loro avviene su Android 4.3. Riceviamo segnalazioni di questo da Crittercism da parte degli utenti sul campo.

L'errore è una variazione di: " 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)

Finora non abbiamo avuto fortuna nel riprodurre il problema in casa o nel capire cosa potrebbe averlo causato.

Qualche idea su cosa può causare questo? Qualche idea su come eseguire il debug di questo e scoprire quale parte dell'app causa questo? Tutto ciò che fa luce sulla questione aiuta.

Più 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

Abbiamo risolto il problema arrestando 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();
    }
}

È possibile chiamare il metodo nel ciclo di vita dell'applicazione, come attachBaseContext() . Per lo stesso motivo, puoi anche specificare la produzione del telefono per risolvere il problema, tocca a te.


FinalizeQueue potrebbe essere troppo lungo

penso che java potrebbe richiedere GC.SuppressFinalize() e GC.ReRegisterForFinalize() per consentire all'utente di ridurre la lunghezza finalizedQueue in modo esplicito

se il codice sorgente della JVM è disponibile, può implementare questo metodo da noi, come ad esempio il creatore di ROM Android


Lo vediamo costantemente, in tutta la nostra app, usando Crashlytics. Il crash di solito accade molto giù nel codice della piattaforma. Un piccolo campionamento:

android.database.CursorWindow.finalize () è scaduto dopo 10 secondi

java.util.regex.Matcher.finalize () è scaduto dopo 10 secondi

android.graphics.Bitmap $ BitmapFinalizer.finalize () è scaduto dopo 10 secondi

org.apache.http.impl.conn.SingleClientConnManager.finalize () scaduto dopo 10 secondi

java.util.concurrent.ThreadPoolExecutor.finalize () scaduto dopo 10 secondi

android.os.BinderProxy.finalize () è scaduto dopo 10 secondi

android.graphics.Path.finalize () è scaduto dopo 10 secondi

I dispositivi su cui questo accade sono in modo schiacciante (ma non esclusivo) i dispositivi prodotti da Samsung. Ciò significa che la maggior parte dei nostri utenti utilizza dispositivi Samsung; alternativamente potrebbe indicare un problema con i dispositivi Samsung. Non sono veramente sicuro.

Suppongo che questo non risponda veramente alle tue domande, ma volevo solo rinforzare il fatto che ciò sembra abbastanza comune e non specifico per la tua applicazione.


Sembra un bug di Android Runtime. Sembra che ci sia un finalizzatore che gira nel suo thread separato e chiama il metodo finalize () sugli oggetti se non sono nel frame corrente dello stacktrace. Ad esempio il seguente codice (creato per verificare questo problema) si è concluso con l'arresto anomalo.

Disponiamo di un cursore che fa qualcosa nel metodo finalize (es. SqlCipher, do close () che si blocca sul database attualmente in uso)

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();
        }
    }
}

E facciamo roba da molto tempo con il cursore aperto:

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();
    }

Ciò causa l'errore seguente:

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 di produzione con SqlCipher è molto simile:

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)

Riprendi: Chiudi i cursori APPENA POSSIBILE. Almeno su Samsung S8 con Android 7 in cui il problema è stato visto.


Una cosa che è invariabilmente vera è che in questo momento, il dispositivo sarebbe soffocante per un po 'di memoria (che di solito è la ragione per cui GC molto probabilmente viene attivato).

Come accennato in precedenza da quasi tutti gli autori, questo problema emerge quando Android tenta di eseguire GC mentre l'app è in background. Nella maggior parte dei casi in cui l'abbiamo osservato, l'utente ha messo in pausa l'app bloccando lo schermo. Ciò potrebbe anche indicare perdite di memoria da qualche parte nell'applicazione o il dispositivo è già caricato troppo. Quindi l'unico modo legittimo per minimizzarlo è:

  • per garantire che non ci siano perdite di memoria, e
  • per ridurre l'ingombro di memoria dell'app in generale.

Full disclosure - Sono l'autore del discorso precedentemente menzionato in TLV DroidCon.

Ho avuto la possibilità di esaminare questo problema su molte applicazioni Android e discuterne con altri sviluppatori che lo hanno incontrato, e siamo arrivati ​​tutti allo stesso punto: questo problema non può essere evitato, ma solo minimizzato.

Ho dato un'occhiata più ravvicinata all'implementazione predefinita del codice del raccoglitore automatico dei rifiuti di Android, per capire meglio perché questa eccezione è generata e su quali potrebbero essere le possibili cause. Ho persino trovato una possibile causa alla radice durante la sperimentazione.

La radice del problema è al punto un dispositivo "Goes to Sleep" per un po '- questo significa che il sistema operativo ha deciso di abbassare il consumo della batteria fermando la maggior parte dei processi User Land per un po' e disattivando Screen, riducendo i cicli della CPU , ecc. In questo modo, si trova su un livello di sistema Linux in cui i processi sono in pausa a metà percorso. Ciò può accadere in qualsiasi momento durante la normale esecuzione dell'applicazione, ma si fermerà a una chiamata di sistema nativa, poiché il cambio di contesto viene eseguito a livello di kernel. Quindi - questo è il punto in cui il GC Dalvik si unisce alla storia. Il codice GC di Dalvik (implementato nel progetto Dalvik nel sito AOSP) non è un codice complicato. Il modo in cui funziona è coperto dalle diapositive di DroidCon. ciò che non ho coperto è il ciclo di base del GC - nel punto in cui il raccoglitore ha una lista di oggetti da finalizzare (e distruggere). la logica del loop alla base può essere semplificata in questo modo:

  1. prendi start_timestamp,
  2. rimuovi l'oggetto per la lista degli oggetti da rilasciare,
  3. release object - finalize() e chiama native destroy() se richiesto,
  4. prendi end_timestamp ,
  5. calcolare ( end_timestamp - starting_timestamp ) e confrontarlo con un valore di timeout codificato di 10 secondi,
  6. se è scaduto il timeout: lanciare concurrent.TimeoutException e terminare il processo.

Considerare ora il seguente scenario:

L'applicazione corre lungo facendo la sua cosa. non si tratta di un'applicazione rivolta all'utente, viene eseguita in background. Durante questa operazione in background, gli oggetti vengono creati, utilizzati e devono essere raccolti per liberare memoria. L'applicazione non infastidisce con un Wakelock, in quanto ciò influisce negativamente sulla batteria e sembra non necessario. questo significa che l'applicazione invocherà il GC di volta in volta. Normalmente le esecuzioni del GC sono completate senza intoppi. A volte (molto raramente) il sistema deciderà di dormire nel mezzo della corsa del GC. Ciò accadrà se si esegue l'applicazione abbastanza a lungo e si monitorano da vicino i registri di memoria Dalvik. Ora - considera la logica del timestamp del ciclo di base del GC - è possibile che il dispositivo avvii la corsa, prendi un start_stamp e vai a dormire alla chiamata destroy() nativa su un oggetto di sistema. quando si sveglia e riprende la corsa, il destroy() termina, e il prossimo end_stamp sarà il tempo impiegato per la chiamata destroy() + il tempo di sonno. Se il tempo di sospensione era lungo: oltre 10 secondi, verrà generata l'eccezione concurrent.timeout.

Ho visto questo nei grafici generati dallo script python di analisi - per le Applicazioni di sistema Android, non solo per le mie app monitorate. raccogli abbastanza log, alla fine lo vedrai.

Linea di fondo:

Il problema non può essere evitato: lo incontrerai se la tua app viene eseguita in background. Puoi mitigare prendendo un wakelock e impedendo al dispositivo di dormire, ma questa è una storia completamente diversa, e un nuovo mal di testa, e forse un altro discorso in un'altra truffa.

È possibile ridurre il problema riducendo le chiamate GC, rendendo meno probabile lo scenario. i suggerimenti sono nelle diapositive.

Non ho ancora avuto la possibilità di esaminare il codice GC di Dalvik 2 (aka ART) - che vanta una nuova funzione di compattazione generazionale, o di eseguire esperimenti su un Lollipop Android.

Aggiunti 7/5/2015:

Dopo aver esaminato l'aggregazione dei report di Crash per questo tipo di crash, sembra che questi arresti anomali dalla versione 5.0+ del sistema operativo Android (Lollipop con ART) rappresentino solo lo 0,5% di questo tipo di arresto. Ciò significa che le modifiche ART GC hanno ridotto la frequenza di questi arresti anomali.

Aggiunto il 01/06/2016:

Sembra che il progetto Android abbia aggiunto molte informazioni su come funziona il GC in Dalvik 2.0 (aka ART). Puoi leggerlo qui - Debugging ART Garbage Collection . Descrive anche alcuni strumenti per ottenere informazioni sul comportamento del GC per la tua app. L'invio di un SIGQUIT al processo dell'app causerà essenzialmente un ANR e scaricherà lo stato dell'applicazione in un file di registro per l'analisi.





garbage-collection