Cómo manejar: java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize () agotó el tiempo de espera después de 10 segundos de error?

Estamos viendo varios TimeoutExceptionsen GcWatcher.finalize, BinderProxy.finalize, y PlainSocketImpl.finalize. Más del 90% de ellos ocurren en Android 4.3. Estamos recibiendo informes de esto de Crittercism de usuarios en el campo.

El error es una variación 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)

Hasta ahora no hemos tenido la suerte de reproducir el problema en casa o descubrir qué podría haberlo causado.

¿Alguna idea de qué puede causar esto? ¿Alguna idea de cómo depurar esto y descubrir qué parte de la aplicación causa esto? Cualquier cosa que arroje luz sobre el tema ayuda.

Más 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 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

Divulgación completa : soy el autor de la charla mencionada anteriormente en TLV DroidCon.

Tuve la oportunidad de examinar este problema en muchas aplicaciones de Android y discutirlo con otros desarrolladores que lo encontraron, y todos llegamos al mismo punto: este problema no puede evitarse, solo minimizarse.

Eché un vistazo más de cerca a la implementación predeterminada del código del recolector de basura de Android, para comprender mejor por qué se lanza esta excepción y cuáles podrían ser las posibles causas. Incluso encontré una posible causa raíz durante la experimentación.

La raíz del problema está en el momento en que un dispositivo "se va a dormir" por un tiempo, esto significa que el sistema operativo ha decidido reducir el consumo de batería al detener la mayoría de los procesos de User Land por un tiempo y apagar la pantalla, lo que reduce los ciclos de la CPU , etc. La forma en que se hace esto es en un nivel de sistema Linux donde los procesos se pausan a mitad de ejecución. Esto puede suceder en cualquier momento durante la ejecución normal de la aplicación, pero se detendrá en una llamada al sistema nativo, ya que el cambio de contexto se realiza en el nivel del núcleo. Entonces, aquí es donde el Dalvik GC se une a la historia.

El código Dalvik GC (tal como se implementó en el proyecto Dalvik en el sitio AOSP) no es un código complicado. La forma básica en que funciona está cubierta en mis diapositivas DroidCon. Lo que no cubrí es el bucle GC básico, en el punto en que el recopilador tiene una lista de Objetos para finalizar (y destruir). La lógica de bucle en la base se puede simplificar así:

1. tomar starting_timestamp,
2. eliminar objeto para lista de objetos para liberar,
3. liberar objeto - finalize()y llamar nativo destroy()si es necesario,
4. tomar end_timestamp,
5. calcular ( end_timestamp - starting_timestamp) y comparar con un valor de tiempo de espera codificado de 10 segundos,
6. Si se agotó el tiempo de espera, tira java.util.concurrent.TimeoutExceptiony finaliza el proceso.

Ahora considere el siguiente escenario:

La aplicación se ejecuta haciendo lo suyo.

Esta no es una aplicación orientada al usuario, se ejecuta en segundo plano.

Durante esta operación en segundo plano, los objetos se crean, se usan y se deben recopilar para liberar memoria.

La aplicación no molesta con un WakeLock, ya que esto afectará negativamente a la batería y parece innecesario.

Esto significa que la Aplicación invocará el GC de vez en cuando.

Normalmente, las ejecuciones de GC se completan sin problemas.

A veces (muy raramente) el sistema decidirá dormir en medio de la ejecución del GC.

Esto sucederá si ejecuta su aplicación el tiempo suficiente y monitorea de cerca los registros de memoria de Dalvik.

Ahora, considere la lógica de marca de tiempo del bucle básico de GC: es posible que el dispositivo inicie la ejecución, tome una start_stampy se vaya a dormir en la destroy()llamada nativa en un objeto del sistema.

Cuando se despierte y reanude la ejecución, destroy()finalizará y el siguiente end_stampserá el tiempo que tomó la destroy()llamada + el tiempo de suspensión.

Si el tiempo de sueño fue largo (más de 10 segundos), se java.util.concurrent.TimeoutExceptionarrojará.

He visto esto en los gráficos generados a partir del script de análisis python, para aplicaciones de sistema Android, no solo mis propias aplicaciones monitoreadas.

Recoja suficientes registros y eventualmente lo verá.

Línea de fondo:

El problema no se puede evitar: lo encontrará si su aplicación se ejecuta en segundo plano.

Puede mitigar tomando un WakeLock y evitar que el dispositivo duerma, pero esa es una historia completamente diferente, y un nuevo dolor de cabeza, y tal vez otra charla en otra estafa.

Puede minimizar el problema reduciendo las llamadas de GC, lo que hace que el escenario sea menos probable (hay sugerencias en las diapositivas).

Todavía no he tenido la oportunidad de repasar el código GC Dalvik 2 (también conocido como ART), que cuenta con una nueva función de compactación generacional, o realicé cualquier experimento en un Android Lollipop.

Añadido 7/5/2015:

Después de revisar la agregación de informes de bloqueo para este tipo de bloqueo, parece que estos bloqueos de la versión 5.0+ del sistema operativo Android (Lollipop con ART) solo representan el 0.5% de este tipo de bloqueo. Esto significa que los cambios de ART GC han reducido la frecuencia de estos accidentes.

Añadido 6/1/2016:

Parece que el proyecto de Android ha agregado mucha información sobre cómo funciona el GC en Dalvik 2.0 (también conocido como ART).

Puede leer sobre esto aquí - Depuración de la recolección de basura ART .

También se analizan algunas herramientas para obtener información sobre el comportamiento de GC para su aplicación.

Enviar un SIGQUIT al proceso de su aplicación esencialmente causará un ANR y volcará el estado de la aplicación en un archivo de registro para su análisis.

Esto lo vemos constantemente, en toda nuestra aplicación, usando Crashlytics. El bloqueo generalmente ocurre en el código de la plataforma. Una pequeña muestra:

android.database.CursorWindow.finalize () expiró después de 10 segundos

java.util.regex.Matcher.finalize () expiró después de 10 segundos

android.graphics.Bitmap $ BitmapFinalizer.finalize () expiró después de 10 segundos

org.apache.http.impl.conn.SingleClientConnManager.finalize () expiró después de 10 segundos

java.util.concurrent.ThreadPoolExecutor.finalize () expiró después de 10 segundos

android.os.BinderProxy.finalize () expiró después de 10 segundos

android.graphics.Path.finalize () expiró después de 10 segundos

Los dispositivos en los que esto sucede son abrumadoramente (pero no exclusivamente) dispositivos fabricados por Samsung. Eso podría significar que la mayoría de nuestros usuarios están utilizando dispositivos Samsung; alternativamente, podría indicar un problema con los dispositivos Samsung. No estoy realmente seguro.

Supongo que esto realmente no responde a sus preguntas, pero solo quería reafirmar que esto parece bastante común y no es específico de su aplicación.

Encontré algunas diapositivas sobre este tema.

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

En estas diapositivas, el autor dice que parece ser un problema con GC, si hay muchos objetos u objetos enormes en el montón. La diapositiva también incluye una referencia a una aplicación de muestra y un script de Python para analizar este problema.

https://github.com/oba2cat3/GCTest

https://github.com/oba2cat3/logcat2memorygraph

Además, encontré una pista en el comentario n. ° 3 de este lado: https://code.google.com/p/android/issues/detail?id=53418#c3

Resolvimos el problema deteniendo el 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();
    }
}

Puede llamar al método en el ciclo de vida de la aplicación, como attachBaseContext(). Por la misma razón, también puede especificar la fabricación del teléfono para solucionar el problema, depende de usted.

Los receptores de difusión expiran después de 10 segundos. Posiblemente está haciendo una llamada asincrónica (incorrecta) desde un receptor de transmisión y 4.3 realmente lo detecta.

Aquí hay una solución efectiva de didi para resolver este problema, ya que este error es muy común y difícil de encontrar la causa, se parece más a un problema del sistema, ¿por qué no podemos ignorarlo directamente? Por supuesto que podemos ignorarlo, aquí es el código de muestra:

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

Al establecer un controlador de excepción no capturado predeterminado especial, la aplicación puede cambiar la forma en que se manejan las excepciones no capturadas para aquellos subprocesos que ya aceptarían cualquier comportamiento predeterminado proporcionado por el sistema. Cuando TimeoutExceptionse arroja un objeto no capturado desde un hilo llamado FinalizerWatchdogDaemon, este controlador especial bloqueará la cadena del controlador, no se llamará al controlador del sistema, por lo que se evitará el bloqueo.

A través de la práctica, no se encontraron otros efectos negativos. El sistema GC todavía funciona, los tiempos de espera se alivian a medida que disminuye el uso de la CPU.

Para obtener más información, consulte: https://mp.weixin.qq.com/s/uFcFYO2GtWWiblotem2bGg

Una cosa que es invariablemente cierta es que, en este momento, el dispositivo se estaría asfixiando por algo de memoria (que generalmente es la razón por la cual es muy probable que se active el GC).

Como se mencionó anteriormente por casi todos los autores, este problema surge cuando Android intenta ejecutar GC mientras la aplicación está en segundo plano. En la mayoría de los casos donde lo observamos, el usuario detuvo la aplicación bloqueando su pantalla. Esto también podría indicar una pérdida de memoria en algún lugar de la aplicación o que el dispositivo ya está demasiado cargado. Entonces, la única forma legítima de minimizarlo es:

• para garantizar que no haya pérdidas de memoria, y
• para reducir la huella de memoria de la aplicación en general.

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

El finalizeQueue puede ser demasiado largo

Creo que Java puede requerir GC.SuppressFinalize () & GC.ReRegisterForFinalize () para permitir al usuario reducir la longitud finalizedQueue explícitamente

si el código fuente de JVM está disponible, podemos implementar estos métodos nosotros mismos, como el fabricante de ROM de Android

Parece un error de Android Runtime. Parece que hay un finalizador que se ejecuta en su hilo separado y llama al método finalize () en los objetos si no están en el marco actual del stacktrace. Por ejemplo, el siguiente código (creado para verificar este problema) terminó con el bloqueo.

Tengamos algunos cursores que hagan algo en el método de finalización (por ejemplo, los de SqlCipher, do close () que se bloquea en la base de datos que está actualmente en 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();
        }
    }
}

Y hacemos algunas cosas de larga duración con el cursor abierto:

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

Esto causa el siguiente error:

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 producción con SqlCipher es muy similar:

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)

Reanudar: cierre los cursores lo antes posible. Al menos en Samsung S8 con Android 7 donde se ha visto el problema.

Para las clases que cree (es decir, no son parte de Android) es posible evitar el bloqueo por completo.

Cualquier clase que implemente finalize()tiene una probabilidad inevitable de fallar, como lo explica @oba. Entonces, en lugar de usar finalizadores para realizar la limpieza, use a PhantomReferenceQueue.

Para ver un ejemplo, consulte la implementación en React Native: https://github.com/facebook/react-native/blob/master/ReactAndroid/src/main/java/com/facebook/jni/DestructorThread.java