Как обработать: java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize () истекло время ожидания после ошибок 10 секунд?

Мы видим число TimeoutExceptionsв GcWatcher.finalize, BinderProxy.finalizeи PlainSocketImpl.finalize. 90 +% из них происходят на Android 4.3. Мы получаем сообщения об этом от Crittercism от пользователей на местах.

Ошибка является вариацией: " 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)

До сих пор нам не удавалось воспроизвести проблему дома или выяснить, что могло ее вызвать.

Есть идеи, что может вызвать это? Любая идея, как отладить это и выяснить, какая часть приложения вызывает это? Все, что проливает свет на проблему, помогает.

Больше 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

Полное раскрытие - я автор ранее упомянутой беседы в TLV DroidCon.

У меня была возможность изучить эту проблему во многих приложениях для Android и обсудить ее с другими разработчиками, которые сталкивались с ней - и мы все пришли к одному и тому же вопросу: эту проблему нельзя избежать, только свести к минимуму.

Я более внимательно посмотрел на реализацию кода сборщика мусора Android по умолчанию, чтобы лучше понять, почему выбрасывается это исключение и каковы возможные причины этого. Я даже нашел возможную причину во время экспериментов.

Корень проблемы в том, что устройство некоторое время «спит» - это означает, что ОС решила снизить потребление батареи, на время остановив большинство процессов User Land, и выключив Screen, уменьшив циклы ЦП. и т. д. То, как это делается, - на уровне системы Linux, где процессы приостановлены в середине выполнения. Это может произойти в любое время во время нормального выполнения приложения, но оно остановится на системном вызове Native, поскольку переключение контекста выполняется на уровне ядра. Итак - вот где Dalvik GC присоединяется к истории.

Код Dalvik GC (реализованный в проекте Dalvik на сайте AOSP) не является сложным фрагментом кода. Как это работает, описано в моих слайдах по DroidCon. То, что я не рассмотрел, - это основной цикл GC - в тот момент, когда у сборщика есть список объектов для завершения (и уничтожения). Логика цикла у основания может быть упрощена следующим образом:

1. взять starting_timestamp,
2. удалить объект для списка объектов для освобождения,
3. освободить объект - finalize()и destroy()при необходимости вызвать native
4. взять end_timestamp,
5. рассчитать ( end_timestamp - starting_timestamp) и сравнить с жестко закодированным значением времени ожидания 10 секунд,
6. если истекло время ожидания - бросить java.util.concurrent.TimeoutExceptionи убить процесс.

Теперь рассмотрим следующий сценарий:

Приложение работает, делая свое дело.

Это не пользовательское приложение, оно работает в фоновом режиме.

Во время этой фоновой операции объекты создаются, используются и должны быть собраны для освобождения памяти.

Приложение не работает с WakeLock - это отрицательно скажется на аккумуляторе и кажется ненужным.

Это означает, что приложение будет время от времени вызывать GC.

Обычно GC проходит без заминки.

Иногда (очень редко) система решает спать в середине запуска GC.

Это произойдет, если вы запустите приложение достаточно долго и внимательно наблюдаете за журналами памяти Dalvik.

Теперь - рассмотрим логику временной метки основного цикла GC - устройство может начать выполнение, выполнить start_stampи перейти в спящий режим при destroy()собственном вызове системного объекта.

Когда он проснется и возобновит выполнение, destroy()завершится, и следующим end_stampбудет время, которое потребовалось для destroy()вызова + время ожидания.

Если время сна было долгим (более 10 секунд), java.util.concurrent.TimeoutExceptionбудет выброшено.

Я видел это на графиках, сгенерированных из скрипта Python для анализа - для системных приложений Android, а не только для моих собственных контролируемых приложений.

Соберите достаточно логов, и вы в конечном итоге увидите это.

Нижняя граница:

Эту проблему невозможно избежать - вы столкнетесь с ней, если ваше приложение будет работать в фоновом режиме.

Вы можете смягчить воздействие, взяв WakeLock, и не дать устройству спать, но это совсем другая история, и новая головная боль, и, возможно, еще один разговор в другом мошенничестве.

Вы можете минимизировать проблему, сократив количество вызовов GC - делая сценарий менее вероятным (советы приведены на слайдах).

У меня еще не было возможности просмотреть код GC Dalvik 2 (также известный как ART), который может похвастаться новой функцией сжатия поколений, или провести какие-либо эксперименты на Android Lollipop.

Добавлено 05.07.2015:

После рассмотрения агрегации отчетов о сбоях для этого типа сбоя, похоже, что эти вылеты из версии 5.0+ ОС Android (Lollipop с ART) составляют только 0,5% от этого типа сбоя. Это означает, что изменения ART GC уменьшили частоту этих сбоев.

Добавлено 01.06.2016:

Похоже, проект Android добавил много информации о том, как работает GC в Dalvik 2.0 (он же ART).

Вы можете прочитать об этом здесь - Отладка ART Сборка мусора .

Также обсуждаются некоторые инструменты для получения информации о поведении GC для вашего приложения.

Отправка SIGQUIT процессу вашего приложения по существу вызовет ANR и сохранит состояние приложения в файл журнала для анализа.

Мы видим это постоянно, по всему нашему приложению, используя Crashlytics. Сбой обычно происходит в коде платформы. Небольшая выборка:

Время ожидания для android.database.CursorWindow.finalize () истекло через 10 секунд.

Тайм-аут java.util.regex.Matcher.finalize () через 10 секунд

android.graphics.Bitmap $ BitmapFinalizer.finalize () истекло по истечении 10 секунд

org.apache.http.impl.conn.SingleClientConnManager.finalize () истекло время ожидания через 10 секунд

Тайм-аут java.util.concurrent.ThreadPoolExecutor.finalize () через 10 секунд

Время ожидания для android.os.BinderProxy.finalize () истекло через 10 секунд

Время ожидания для android.graphics.Path.finalize () истекло через 10 секунд.

Устройства, на которых это происходит, в подавляющем большинстве (но не исключительно) являются устройствами, произведенными Samsung. Это может означать, что большинство наших пользователей используют устройства Samsung; альтернативно это может указывать на проблему с устройствами Samsung. Я не совсем уверен.

Я полагаю, что это на самом деле не отвечает на ваши вопросы, но я просто хотел подчеркнуть, что это кажется довольно распространенным явлением и не относится к вашему приложению.

Я нашел несколько слайдов по этой проблеме.

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

На этих слайдах автор рассказывает, что, похоже, проблема с GC, если в куче много объектов или огромных объектов. На слайде также есть ссылка на пример приложения и скрипт на Python для анализа этой проблемы.

https://github.com/oba2cat3/GCTest

https://github.com/oba2cat3/logcat2memorygraph

Кроме того, я нашел подсказку в комментарии № 3 на этой стороне: https://code.google.com/p/android/issues/detail?id=53418#c3

Мы решили проблему, остановив 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();
    }
}

Вы можете вызвать метод в жизненном цикле приложения, например attachBaseContext(). По той же причине вы также можете указать производителя телефона, чтобы решить проблему, решать вам.

Тайм-аут приемников вещания через 10 секунд. Возможно, вы делаете асинхронный (неправильный) вызов от широковещательного приемника, а 4.3 фактически обнаруживает его.

Вот эффективное решение от Didi для решения этой проблемы, так как эта ошибка очень распространена и ее трудно найти, она больше похожа на системную проблему. Почему мы не можем игнорировать ее напрямую? Конечно, мы можем игнорировать ее, Здесь это пример кода:

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

Установив специальный обработчик неперехваченных исключений по умолчанию, приложение может изменить способ обработки неперехваченных исключений для тех потоков, которые уже приняли бы любое поведение по умолчанию, предоставленное системой. Когда TimeoutExceptionиз именованного потока выбрасывается uncaught FinalizerWatchdogDaemon, этот специальный обработчик блокирует цепочку обработчиков, системный обработчик вызываться не будет, поэтому сбоя избежать не будет.

На практике никаких других негативных последствий обнаружено не было. Система GC все еще работает, таймауты уменьшаются по мере уменьшения загрузки процессора.

Для получения дополнительной информации см .: https://mp.weixin.qq.com/s/uFcFYO2GtWWiblotem2bGg

Одна вещь, которая неизменно верна, состоит в том, что в это время устройство задыхается от некоторой памяти (что обычно является причиной того, что GC, скорее всего, сработает).

Как уже упоминалось почти всеми авторами ранее, эта проблема возникает, когда Android пытается запустить GC, когда приложение находится в фоновом режиме. В большинстве случаев, когда мы это наблюдали, пользователь приостанавливал приложение, блокируя свой экран. Это также может указывать на утечку памяти где-либо в приложении или на устройство, уже загруженное. Таким образом, единственный законный способ минимизировать это:

• чтобы убедиться в отсутствии утечек памяти, и
• чтобы уменьшить объем памяти приложения в целом.

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

FinalizeQueue может быть слишком длинным

я думаю, что Java может потребовать GC.SuppressFinalize () и GC.ReRegisterForFinalize (), чтобы позволить пользователю явно уменьшить длину finalizedQueue

если исходный код JVM доступен, мы можем реализовать этот метод самостоятельно, например, Android ROM Maker

Это похоже на ошибку Android Runtime. Кажется, что есть финализатор, который работает в отдельном потоке и вызывает метод finalize () для объектов, если они не находятся в текущем кадре трассировки стека. Например, следующий код (созданный для проверки этой проблемы) завершился сбоем.

Давайте возьмем некоторый курсор, который делает что-то в методе finalize (например, SqlCipher, do close (), который привязывается к базе данных, которая используется в данный момент)

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

И мы делаем несколько длительных вещей, открыв курсор:

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

Это вызывает следующую ошибку:

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)

Вариант производства с SqlCipher очень похож:

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)

Резюме: Закрыть курсоры как можно скорее. По крайней мере, на Samsung S8 с Android 7, где проблема была замечена.

Для классов, которые вы создаете (то есть не являетесь частью Android), можно полностью избежать сбоя.

Любой реализующий класс finalize()имеет некоторую неизбежную вероятность сбоя, как объясняет @oba. Таким образом, вместо использования финализаторов для выполнения очистки, используйте PhantomReferenceQueue.

Для примера посмотрите реализацию в React Native: https://github.com/facebook/react-native/blob/master/ReactAndroid/src/main/java/com/facebook/jni/DestructorThread.java