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

android memory management

Question

Estamos viendo un número de TimeoutExceptions en GcWatcher.finalize, BinderProxy.finalize y PlainSocketImpl.finalize . 90% de ellos suceden en Android 4.3. Estamos recibiendo informes de Crittercism de los 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 suerte reproduciendo el problema en casa o averiguando qué pudo haberlo causado.

¿Alguna idea de lo que 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

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

Answer 1

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 se puede evitar, solo se minimiza.

Eché un vistazo más de cerca a la implementación predeterminada del código de recopilador de basura de Android, para comprender mejor por qué se lanzó 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 punto en que un dispositivo "se va a dormir" durante un tiempo: esto significa que el sistema operativo ha decidido reducir el consumo de la batería deteniendo la mayoría de los procesos de User Land por un tiempo y apagando la pantalla, reduciendo los ciclos de CPU , etc. La forma en que esto se hace - está en un nivel de sistema Linux donde los procesos están en pausa 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 del sistema nativo, ya que el cambio de contexto se realiza en el nivel del kernel. Entonces, aquí es donde el Dalvik GC se une a la historia. El código Dalvik GC (implementado en el proyecto Dalvik en el sitio AOSP) no es una pieza complicada de código. La forma básica en que funciona está cubierta en mis diapositivas DroidCon. Lo que no he cubierto es el ciclo GC básico: en el punto donde 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 la lista de objetos para lanzar,
3. release object - finalize() y llama a native destroy() si es necesario,
4. tomar end_timestamp ,
5. calcular ( end_timestamp - starting_timestamp ) y comparar con un valor de tiempo de espera codificado duro de 10 segundos,
6. si se ha alcanzado el tiempo de espera - throw the concurrent.TimeoutException y mata el proceso.

Ahora considere la siguiente situación:

La aplicación corre a lo largo de hacer su trabajo. esta no es una aplicación para el usuario, se ejecuta en segundo plano. Durante esta operación en segundo plano, los Objetos se crean, usan y necesitan ser recolectados 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 carreras de GC se completan sin problemas. A veces (muy raramente) el sistema decidirá dormir en el medio de la carrera del GC. Esto sucederá si ejecuta su aplicación el tiempo suficiente y supervisa de cerca los registros de memoria Dalvik. Ahora, considere la lógica de la marca de tiempo del ciclo de GC básico: es posible que el dispositivo inicie la ejecución, tome una marca de inicio y vaya a la llamada nativa destroy() en un objeto del sistema. cuando se despierta y reanuda la ejecución, el destroy() finalizará, y el siguiente end_stamp será el tiempo que tomó la llamada destroy() + el tiempo de suspensión. Si el tiempo de suspensión fue largo, más de 10 segundos, se lanzará la excepción concurrent.timeout.

Lo he visto en los gráficos generados a partir del script python de análisis, para aplicaciones del sistema Android, no solo en mis propias aplicaciones monitoreadas. recopile suficientes registros, eventualmente lo verá.

Línea de fondo:

No se puede evitar el problema: lo encontrará si su aplicación se ejecuta en segundo plano. Puedes mitigar tomando un wakelock y evitar que el dispositivo duerma, pero esa es una historia completamente diferente, y un nuevo dolor de cabeza, y quizás otra charla en otro engaño.

Puede minimizar el problema reduciendo las llamadas de GC, lo que hace que el escenario sea menos probable. consejos están en las diapositivas.

Todavía no he tenido la oportunidad de repasar el código GC de Dalvik 2 (también conocido como ART), que cuenta con una nueva característica de compactación generacional, o ha realizado experimentos con un Lollipop de Android.

Agregado el 7/5/2015:

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

Agregado 01/06/2016:

Parece que el proyecto 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 recolección de basura ART . También se describen algunas herramientas para obtener información sobre el comportamiento del 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 a un archivo de registro para su análisis.

Answer 2

El finalizeQueue puede ser demasiado largo

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

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

Answer 3

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 haber un problema con GC, si hay muchos objetos u objetos grandes en el montón. La diapositiva también incluye una referencia a una aplicación de ejemplo 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 # 3 en este lado: https://code.google.com/p/android/issues/detail?id=53418#c3

Answer 4

Parece un error de Android Runtime. Parece haber un finalizador que se ejecuta en su subproceso independiente y llama al método finalize () en los objetos si no están en el marco actual de la pila de seguimiento. Por ejemplo, el siguiente código (creado para verificar este problema) finalizó con el bloqueo.

Tengamos un cursor que haga algo en el método de finalización (p. Ej., 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 largas corriendo 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)

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

Answer 5

Solucionamos 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.

Answer 6

Tiempo de espera de los receptores de transmisión después de 10 segundos. Es posible que realice una llamada asincrónica (errónea) desde un receptor de difusión y 4.3 realmente lo detecte.

Answer 7

Una cosa que es invariablemente cierta es que, en este momento, el dispositivo sería sofocante para algo de memoria (que generalmente es la razón por la que el GC probablemente se dispare).

Como mencionaron casi todos los autores anteriormente, este problema aparece cuando Android intenta ejecutar GC mientras la aplicación está en segundo plano. En la mayoría de los casos en que lo observamos, el usuario pausó la aplicación al bloquear 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 manera 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.

Answer 8

Vemos esto constantemente, en toda nuestra aplicación, usando Crashlytics. Por lo general, la falla se produce en el código de la plataforma. Una pequeña muestra:

android.database.CursorWindow.finalize () agotó el tiempo de espera después de 10 segundos

java.util.regex.Matcher.finalize () agotó el tiempo de espera después de 10 segundos

android.graphics.Bitmap $ BitmapFinalizer.finalize () agotó el tiempo de espera después de 10 segundos

org.apache.http.impl.conn.SingleClientConnManager.finalize () Tiempo de espera agotado después de 10 segundos

java.util.concurrent.ThreadPoolExecutor.finalize () agotó el tiempo de espera después de 10 segundos

android.os.BinderProxy.finalize () agotó el tiempo de espera después de 10 segundos

android.graphics.Path.finalize () agotó el tiempo de espera después de 10 segundos

Los dispositivos en los que esto sucede son abrumadoramente (pero no exclusivamente) dispositivos fabricados por Samsung. Eso solo podría significar que la mayoría de nuestros usuarios usan 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 reforzar que esto parece bastante común, y no es específico de su aplicación.

Answer 9

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