Jak obsłużyć: java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize () przekroczył limit czasu po 10 sekundach błędów?

Widzimy wiele TimeoutExceptionsw GcWatcher.finalize, BinderProxy.finalize, i PlainSocketImpl.finalize. Ponad 90% z nich dzieje się na Androidzie 4.3. Otrzymujemy raporty od Crittercism od użytkowników w terenie.

Błąd jest odmianą: „ 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)

Jak dotąd nie udało nam się odtworzyć problemu w domu ani ustalić, co mogło go spowodować.

Jakieś pomysły, co może to spowodować? Masz pomysł, jak to debugować i dowiedzieć się, która część aplikacji to powoduje? Wszystko, co rzuca światło na ten problem, pomaga.

Więcej 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

Pełne ujawnienie - jestem autorem wspomnianego wcześniej wystąpienia w TLV DroidCon.

Miałem okazję zbadać ten problem w wielu aplikacjach na Androida i omówić go z innymi programistami, którzy go napotkali - i wszyscy doszliśmy do tego samego punktu: tego problemu nie można uniknąć, tylko zminimalizować.

Przyjrzałem się bliżej domyślnej implementacji kodu modułu zbierającego elementy systemu Android, aby lepiej zrozumieć, dlaczego ten wyjątek jest zgłaszany i jakie mogą być możliwe przyczyny. Podczas eksperymentów znalazłem nawet możliwą przyczynę źródłową.

Przyczyną problemu jest moment, w którym urządzenie „przechodzi w stan uśpienia” na chwilę - oznacza to, że system operacyjny zdecydował się obniżyć zużycie baterii, zatrzymując na chwilę większość procesów User Land i wyłączając ekran, zmniejszając cykle procesora itd. Sposób, w jaki to się robi - odbywa się na poziomie systemu Linux, gdzie procesy są wstrzymywane w trakcie wykonywania. Może się to zdarzyć w dowolnym momencie podczas normalnego wykonywania aplikacji, ale zatrzyma się przy wywołaniu systemu natywnego, ponieważ przełączanie kontekstu odbywa się na poziomie jądra. A więc - w tym miejscu Dalvik GC dołącza do historii.

Kod Dalvik GC (wdrożony w projekcie Dalvik w witrynie AOSP) nie jest skomplikowanym fragmentem kodu. Podstawowy sposób działania jest opisany na moich slajdach DroidCon. To, czego nie opisałem, to podstawowa pętla GC - w miejscu, w którym kolektor ma listę obiektów do sfinalizowania (i zniszczenia). Logikę pętli u podstawy można uprościć w następujący sposób:

1. wziąć starting_timestamp,
2. usuń obiekt do listy obiektów do zwolnienia,
3. zwolnij obiekt - finalize()i w destroy()razie potrzeby wywołaj natywny ,
4. wziąć end_timestamp,
5. oblicz ( end_timestamp - starting_timestamp) i porównaj z zakodowaną wartością limitu czasu wynoszącą 10 sekund,
6. jeśli upłynął limit czasu - wyrzuć java.util.concurrent.TimeoutExceptioni zakończ proces.

Rozważmy teraz następujący scenariusz:

Aplikacja działa dalej i robi swoje.

To nie jest aplikacja dla użytkownika, działa w tle.

Podczas tej operacji w tle obiekty są tworzone, używane i muszą zostać zebrane w celu zwolnienia pamięci.

Aplikacja nie przejmuje się WakeLockiem - odbije się to niekorzystnie na baterii i wydaje się niepotrzebne.

Oznacza to, że Aplikacja będzie od czasu do czasu wywoływać GC.

Zwykle przebiegi GC kończą się bez żadnych problemów.

Czasami (bardzo rzadko) system zdecyduje się przespać w środku przebiegu GC.

Stanie się tak, jeśli będziesz uruchamiać aplikację wystarczająco długo i uważnie monitorować dzienniki pamięci Dalvik.

Teraz - weź pod uwagę logikę znacznika czasu podstawowej pętli GC - urządzenie może rozpocząć działanie, pobrać start_stampi przejść w stan uśpienia podczas destroy()natywnego wywołania obiektu systemowego.

Kiedy się obudzi i wznowi bieg, destroy()zakończy się, a następnym end_stampbędzie czas, w którym odebrał destroy()połączenie + czas snu.

Jeśli czas uśpienia był długi (ponad 10 sekund), java.util.concurrent.TimeoutExceptionzostanie wyrzucony.

Widziałem to na wykresach wygenerowanych ze skryptu analizy w języku Python - dla aplikacji systemu Android, a nie tylko dla moich własnych monitorowanych aplikacji.

Zbierz wystarczającą liczbę dzienników, a w końcu to zobaczysz.

Konkluzja:

Problemu nie da się uniknąć - napotkasz go, jeśli Twoja aplikacja będzie działać w tle.

Możesz złagodzić, biorąc WakeLock i uniemożliwić urządzeniu spanie, ale to zupełnie inna historia i nowy ból głowy, a może kolejna rozmowa w innym oszustwie.

Możesz zminimalizować problem, zmniejszając wywołania GC - dzięki czemu scenariusz jest mniej prawdopodobny (wskazówki znajdują się na slajdach).

Nie miałem jeszcze okazji omówić kodu GC Dalvik 2 (aka ART) - który oferuje nową funkcję kompaktowania generacji, ani nie przeprowadziłem żadnych eksperymentów na Android Lollipop.

Dodano 05.07.2015:

Po zapoznaniu się z agregacją raportów o awariach dla tego typu awarii wygląda na to, że te awarie z wersji 5.0+ systemu Android (Lollipop z ART) stanowią tylko 0,5% tego typu awarii. Oznacza to, że zmiany ART GC zmniejszyły częstotliwość tych awarii.

Dodano 06.01.2016:

Wygląda na to, że projekt Android dodał wiele informacji o tym, jak działa GC w Dalvik 2.0 (aka ART).

Możesz o tym przeczytać tutaj - Debugging ART Garbage Collection .

Omówiono również niektóre narzędzia do uzyskiwania informacji o zachowaniu GC dla Twojej aplikacji.

Wysłanie polecenia SIGQUIT do procesu aplikacji zasadniczo spowoduje błąd ANR i zrzuci stan aplikacji do pliku dziennika w celu analizy.

Widzimy to nieustannie w całej naszej aplikacji, używając Crashlytics. Awaria zwykle występuje w kodzie platformy. Mała próbka:

android.database.CursorWindow.finalize () przekroczył limit czasu po 10 sekundach

java.util.regex.Matcher.finalize () przekroczył limit czasu po 10 sekundach

android.graphics.Bitmap $ BitmapFinalizer.finalize () przekroczył limit czasu po 10 sekundach

org.apache.http.impl.conn.SingleClientConnManager.finalize () przekroczył limit czasu po 10 sekundach

java.util.concurrent.ThreadPoolExecutor.finalize () przekroczył limit czasu po 10 sekundach

android.os.BinderProxy.finalize () przekroczył limit czasu po 10 sekundach

android.graphics.Path.finalize () przekroczył limit czasu po 10 sekundach

Urządzenia, na których to się dzieje, to w przeważającej większości (ale nie wyłącznie) urządzenia produkowane przez firmę Samsung. Może to po prostu oznaczać, że większość naszych użytkowników korzysta z urządzeń Samsung; alternatywnie może to oznaczać problem z urządzeniami Samsung. Nie jestem do końca pewny.

Przypuszczam, że to tak naprawdę nie odpowiada na twoje pytania, ale chciałem tylko podkreślić, że wydaje się to dość powszechne i nie jest specyficzne dla twojej aplikacji.

Znalazłem kilka slajdów dotyczących tego problemu.

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

Na tych slajdach autor mówi, że wydaje się, że problem z GC jest, jeśli w stercie jest dużo obiektów lub dużych obiektów. Slajd zawiera również odniesienie do przykładowej aplikacji i skryptu w języku Python do analizy tego problemu.

https://github.com/oba2cat3/GCTest

https://github.com/oba2cat3/logcat2memorygraph

Ponadto znalazłem wskazówkę w komentarzu nr 3 po tej stronie: https://code.google.com/p/android/issues/detail?id=53418#c3

Rozwiązaliśmy problem, zatrzymując plik 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();
    }
}

Możesz wywołać metodę w cyklu życia aplikacji, na przykład attachBaseContext(). Z tego samego powodu możesz również określić producenta telefonu, aby rozwiązać problem, to zależy od Ciebie.

Przekroczono limit czasu odbiorników transmisji po 10 sekundach. Prawdopodobnie wykonujesz asynchroniczne wywołanie (źle) z odbiornika rozgłoszeniowego i 4.3 faktycznie je wykrywa.

Oto skuteczne rozwiązanie didi do rozwiązania tego problemu, ponieważ ten błąd jest bardzo powszechny i ​​trudny do znalezienia przyczyny, Wygląda bardziej na problem systemowy, dlaczego nie możemy go zignorować bezpośrednio？ Oczywiście możemy go zignorować, tutaj to przykładowy kod:

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

Ustawiając specjalną domyślną procedurę obsługi nieprzechwyconych wyjątków, aplikacja może zmienić sposób, w jaki nieprzechwycone wyjątki są obsługiwane dla tych wątków, które już zaakceptowałyby jakiekolwiek domyślne zachowanie dostarczone przez system. Kiedy nieprzechwycony TimeoutExceptionzostanie wyrzucony z wątku o nazwie FinalizerWatchdogDaemon, ten specjalny program obsługi zablokuje łańcuch obsługi, program obsługi systemu nie zostanie wywołany, więc unikniemy awarii.

Dzięki praktyce nie znaleziono innych złych skutków. System GC nadal działa, przekroczenia limitów czasu są zmniejszane wraz ze spadkiem użycia procesora.

Aby uzyskać więcej informacji, zobacz: https://mp.weixin.qq.com/s/uFcFYO2GtWWiblotem2bGg

Jedna rzecz, która jest niezmiennie prawdziwa, to fakt, że w tym czasie urządzenie dusiłoby się z powodu jakiejś pamięci (co zwykle jest przyczyną najprawdopodobniej wyzwalania GC).

Jak wspomniano wcześniej przez prawie wszystkich autorów, ten problem pojawia się, gdy Android próbuje uruchomić GC, gdy aplikacja działa w tle. W większości przypadków, w których to zaobserwowaliśmy, użytkownik wstrzymywał aplikację, blokując ekran. Może to również wskazywać na wyciek pamięci w aplikacji lub zbyt duże obciążenie urządzenia. Więc jedynym legalnym sposobem na zminimalizowanie tego jest:

• aby upewnić się, że nie ma wycieków pamięci, i
• aby ogólnie zmniejszyć zużycie pamięci przez aplikację.

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 może być za długa

Myślę, że java może wymagać GC.SuppressFinalize () i GC.ReRegisterForFinalize (), aby umożliwić użytkownikowi jawne zmniejszenie długości finalizedQueue

jeśli kod źródłowy maszyny JVM jest dostępny, możemy zaimplementować tę metodę samodzielnie, na przykład Android ROM Maker

Wygląda na to, że błąd Android Runtime. Wydaje się, że istnieje finalizator, który działa w oddzielnym wątku i wywołuje metodę finalize () na obiektach, jeśli nie znajdują się one w bieżącej ramce śledzenia stosu. Na przykład następujący kod (stworzony w celu weryfikacji tego problemu) zakończył się awarią.

Niech jakiś kursor robi coś w metodzie finalize (np. Te SqlCipher, wykonaj close (), który blokuje bazę danych, która jest aktualnie używana)

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

I robimy kilka długotrwałych rzeczy z otwartym kursorem:

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

Powoduje to następujący błąd:

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)

Wariant produkcyjny z SqlCipher jest bardzo podobny:

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)

Wznów: Zamknij kursory jak najszybciej. Przynajmniej na Samsungu S8 z Androidem 7, gdzie problem został zauważony.

W przypadku klas, które tworzysz (tj. Nie są częścią systemu Android), można całkowicie uniknąć awarii.

Każda klasa, która implementuje, finalize()ma pewne nieuniknione prawdopodobieństwo awarii, jak wyjaśniono w @oba. Dlatego zamiast używać finalizatorów do czyszczenia, użyj pliku PhantomReferenceQueue.

Na przykład sprawdź implementację w React Native: https://github.com/facebook/react-native/blob/master/ReactAndroid/src/main/java/com/facebook/jni/DestructorThread.java