Find out the reason of ANR using Android Profiler

Question

My application pops up the ANR (Application is not responding) dialog. For a long time I am trying to solve this issue. I have made lots of optimisations and finally my main thread takes 2~3 million microseconds however that is not enough too.

Also nearly all service calls are done with Rxjava. I do not know if the callbacks are belong to them.

When I use Android Profiler for my specific activity that shows the popup, there are 2 processes that take too long.

First one is onCreate method.

Second one is handleCallback. I could not be able to reduce the time of those process. I do not know how to do about it and what it is.

I tried to use async tasks but still have the same problem even though I have achieved some results.

You may see the traces.txt file via this link => gofile.io/?c=BKXCJ2

UPDATE:

I killed the app when it popped up the ANR dialog and these are the last log lines:

2019-11-27 16:36:53.856 13843-14117/br.com.gomus.androidapp D/DownloadInteractor: addSongDownloadedToCurrentPlaylist
2019-11-27 16:36:53.858 13843-14117/br.com.gomus.androidapp D/DownloadRepositoryImpl: File download and update status finished, should verify all files download status
2019-11-27 16:36:53.860 13843-14117/br.com.gomus.androidapp D/DownloadRepositoryImpl: File download and update status concluded with success emitting progress
2019-11-27 16:36:53.863 13843-14117/br.com.gomus.androidapp D/DownloadRepositoryImpl: mItemsDownloaded: 4 mTotalItems14
2019-11-27 16:36:53.866 13843-14117/br.com.gomus.androidapp D/DownloadRepositoryImpl: Current progress : 28 %
2019-11-27 16:36:53.868 13843-14117/br.com.gomus.androidapp D/DownloadRepositoryImpl: mCallback != null
2019-11-27 16:36:53.881 13843-14113/br.com.gomus.androidapp D/DownloadRepositoryImpl: Starting download of file at url http://s3.amazonaws.com/br.com.gomus.songs/2124950971
2019-11-27 16:36:53.925 13843-14143/br.com.gomus.androidapp D/OkHttp: --> GET http://s3.amazonaws.com/br.com.gomus.songs/2124950971
2019-11-27 16:36:53.926 13843-14143/br.com.gomus.androidapp D/OkHttp: --> END GET
2019-11-27 16:36:53.929 13843-14143/br.com.gomus.androidapp D/WebService: --> GET http://s3.amazonaws.com/br.com.gomus.songs/2124950971
2019-11-27 16:36:53.931 13843-14143/br.com.gomus.androidapp D/WebService: --> END GET
2019-11-27 16:36:54.266 13843-14143/br.com.gomus.androidapp D/WebService: <-- 200 OK http://s3.amazonaws.com/br.com.gomus.songs/2124950971 (330ms)
2019-11-27 16:36:54.269 13843-14143/br.com.gomus.androidapp D/WebService: x-amz-id-2: njC3Sfnqwkg+tJsRdGem8sNtQrJBIKSK1JgrL4SZvLCp7Cosw1mKLfdgARtOjE+ubVDa8KDE1Ig=
2019-11-27 16:36:54.271 13843-14143/br.com.gomus.androidapp D/WebService: x-amz-request-id: CD185B026FA3B166
2019-11-27 16:36:54.274 13843-14143/br.com.gomus.androidapp D/WebService: Date: Wed, 27 Nov 2019 18:36:55 GMT
2019-11-27 16:36:54.276 13843-14143/br.com.gomus.androidapp D/WebService: Last-Modified: Wed, 06 Jul 2011 17:23:22 GMT
2019-11-27 16:36:54.279 13843-14143/br.com.gomus.androidapp D/WebService: ETag: "e9c453f55a3f41bc04ec84de14f0861f"
2019-11-27 16:36:54.281 13843-14143/br.com.gomus.androidapp D/WebService: Accept-Ranges: bytes
2019-11-27 16:36:54.283 13843-14143/br.com.gomus.androidapp D/WebService: Content-Type: audio/mpeg
2019-11-27 16:36:54.286 13843-14143/br.com.gomus.androidapp D/WebService: Content-Length: 3390468
2019-11-27 16:36:54.288 13843-14143/br.com.gomus.androidapp D/WebService: Server: AmazonS3
2019-11-27 16:36:56.069 13843-13843/? D/ViewRootImpl@810767d[DownloadContentActivity]: MSG_WINDOW_FOCUS_CHANGED 0 1
2019-11-27 16:36:56.074 13843-13843/? D/InputMethodManager: prepareNavigationBarInfo() DecorView@2321ffe[DownloadContentActivity]
2019-11-27 16:36:56.075 13843-13843/? D/InputMethodManager: getNavigationBarColor() -855310

I added the related code in here. Could someone tell me if there is an inconvenience in this code that would have caused the ANR pop-up?

DownloadContentActivity

handlerThread = new HandlerThread("MyHandlerThread");
    handlerThread.start();
    Looper looper = handlerThread.getLooper();
    Handler handler = new Handler(looper);

    handler.post(new Runnable(){
        @Override
        public void run() {
            mViewModel.startDownload();
        }
    });

DownloadContentViewModel

public void startDownload() {
    mInteractor.startDownload(DownloadContentViewModel.this::downloadResult);
    log(Log.DEBUG, TAG, "Thread.currentThread().getName() " + Thread.currentThread().getName());
}

DownloadContentInteractorImpl

@Override
public void startDownload(Action1<Result<Void>> resultAction) {
    log(Log.DEBUG, TAG, "Thread.currentThread().getName() " + Thread.currentThread().getName());

    mDownloadContentRepository.startDownload(resultAction);
}

DownloadRepositoryImpl

In this method, there is a 3 cascading call which are; downloadPendentSongs, downloadPendentSpots and dowloadPendentVideos. I will just share one of them because all of them has the same implementation. Only downloadPendentVideos will show the action result since it is the last call so that I added its implementation too.

@Override
public void startDownload(Action1<Result<Void>> resultAction) {
    log(Log.DEBUG, TAG, "Thread.currentThread().getName() startDownload" + Thread.currentThread().getName());

    checkPreviousError();
    mNetworkStatus.isOnline(isOnline -> {
        log(Log.DEBUG, TAG, "isOnline Thread.currentThread().getName() " + Thread.currentThread().getName());

        if (isOnline) {
            
            downloadPendentSongs(resultAction,
                    f -> {

                        log(Log.DEBUG, TAG, "downloadPendentSongs Thread.currentThread().getName() " + Thread.currentThread().getName());
                        log(Log.DEBUG, TAG, "All songs download processed with success.");
//                                  log(Log.DEBUG, TAG, "JUST TO TEST = Downloaded file location is "+ f.get(0).getAbsolutePath());
                        downloadPendentSpots(resultAction,

                                f1 -> {
                                    log(Log.DEBUG, TAG, "downloadPendentSpots Thread.currentThread().getName() " + Thread.currentThread().getName());

                                    log(Log.DEBUG, TAG, "All spots download processed with success");
                                    downloadPendentVideos(resultAction);
                                }
                                
                        );
                    });


        } else {
            mHasErrors = true;

            resultAction.call(Result.getNetworkError());
        }
    });

}

NetworkStatusImpl

@Override
public void isOnline(Action1<Boolean> resultAction) {
    log(Log.DEBUG, "NetworkStatusImpl", "Thread.currentThread().getName() " + Thread.currentThread().getName());

    CheckConnectionTask task = new CheckConnectionTask(resultAction);
    task.executeOnExecutor(AsyncTask.THREAD_POOL_EXECUTOR, null);
}

CheckConnectionTask

@Override
protected Void doInBackground(Void... voids) {

    log(Log.DEBUG,TAG,"success HyperLog");
    log(Log.DEBUG, TAG, "doInBackground");
    log(Log.DEBUG, "doInBackground", "Thread.currentThread().getName() " + Thread.currentThread().getName());

    try {

        Socket sock = new Socket();
        InetSocketAddress sockaddr = new InetSocketAddress("8.8.8.8", 53);
        sock.connect(sockaddr, NETWORK_TIMEOUT_MS);
        sock.close();
        log(Log.DEBUG,TAG, "doInBackground try");

        mConnectionResult = true;
    } catch (Exception e) {
        Log.e( TAG, "doInBackground error caught"+e.getMessage());

        mConnectionResult = false;
    }


    mResultConnection.call(mConnectionResult);

    return null;
}


@Override
protected void onPostExecute(Void aVoid) {
   // log(Log.DEBUG,TAG, "onPostExecute");

    super.onPostExecute(aVoid);
}

DownloadRepositoryImpl

private void downloadPendentSongs(Action1<Result<Void>> resultAction,
                                  Action1<List<File>> onDownloadFinished) {
    log(Log.DEBUG, TAG, "Fetching pendent download songs");
    log(Log.DEBUG, TAG, "downloadPendentSongs Thread.currentThread().getName() " + Thread.currentThread().getName());


    getPendentDownloadEntity(mSongDao,
            result -> {
                if (result.isSuccess) {
                    Gson gson = new Gson();
                    String pendentSong = gson.toJson(result.data);
                    log(Log.DEBUG, TAG, result.data.size() + " ,pendent song(s) found"+pendentSong);
                    log(Log.DEBUG, TAG, "getPendentDownloadEntity Thread.currentThread().getName() " + Thread.currentThread().getName());

                    if (result.data.size() > 0) {
                        downloadSongs(result.data, resultAction, onDownloadFinished);
                    } else {
                        onDownloadFinished.call(new ArrayList<>());
                        log(Log.DEBUG, TAG, "downloadPendentSongs result.data.size() > 0");

                    }
                } else {
                    log(Log.DEBUG, TAG, result.data.size() + " downloadPendentSongs error");

                    mHasErrors = true;
                    resultAction.call(Result.getError(result.error));
                }
            }
    );
}



private <T extends RealmObject> void getPendentDownloadEntity(BaseDao<T> dao,
                                                              Action1<Result<List<T>>> resultsAction) {
    log(Log.DEBUG, TAG, "getPendentDownloadEntity Thread.currentThread().getName() " + Thread.currentThread().getName());

    dao.find(this::getPendentEntityQuery, resultsAction);
}

DownloadRepositoryImpl

private void downloadSongs(List<Song> data, Action1<Result<Void>> resultAction, Action1<List<File>> onDownloadFinished) {
    log(Log.DEBUG, TAG, "Starting download of pendent songs");
    log(Log.DEBUG, TAG, "Thread.currentThread().getName() " + Thread.currentThread().getName());

    //if(data.size()>0 && data.get(0).getId()!=0){
        downloadData(
                mSongDao,
                data,
                Song::getId,
                Song::getUrl,
                resultAction,
                (result, file) -> updateSongStatus(result, file == null ? "" : file.getAbsolutePath(), resultAction),
                onDownloadFinished
        );
    //}
}



private void downloadVideos(List<Video> data, Action1<Result<Void>> resultAction) {

    log(Log.DEBUG, TAG, "downloadVideos Thread.currentThread().getName() " + Thread.currentThread().getName());

    log(Log.DEBUG, TAG, "Starting download of pendent videos");
    downloadData(
            mVideoDao,
            data,
            Video::getId,
            Video::getUrl,
            resultAction,
            (result, file) -> updateVideoStatus(result, file.getAbsolutePath(), resultAction),
            f -> {
                checkMustNotifyDownloadFinished(resultAction);
                log(Log.DEBUG, TAG, "checkMustNotifyDownloadFinished downloadVideos Thread.currentThread().getName() " + Thread.currentThread().getName());

                log(Log.DEBUG, TAG, "All pendent downloads were processed without success guarantee.");
            }
    );
}

checkMustNotifyDownloadFinished

private void checkMustNotifyDownloadFinished(Action1<Result<Void>> resultAction) {
    log(Log.DEBUG, TAG, "checkMustNotifyDownloadFinished Thread.currentThread().getName() " + Thread.currentThread().getName());

    if (mItemsDownloaded == mTotalItems) {
        if (!mHasErrors) {
            onAllFilesDownloadFinished(resultAction);
        }
    } else {
        log(Log.DEBUG, TAG, "File download and update status concluded with success emitting progress");
        if (mCallback != null){
            mCallback.onReceiveProgress(getProgress());
            log(Log.DEBUG, TAG, "mCallback != null");

        }
    }
}

onAllFilesDownloadFinished

private void onAllFilesDownloadFinished(Action1<Result<Void>> resultAction) {
    log(Log.DEBUG, TAG, "All files download with success emitting success result");
    log(Log.DEBUG, TAG, "onAllFilesDownloadFinished Thread.currentThread().getName() " + Thread.currentThread().getName());

    if (mCallback != null)
        mCallback.onReceiveProgress(getProgress());
    resultAction.call(Result.getData());
    mHasErrors = false;
    mItemsDownloaded = 0;
    //when pendent downloads are done why do not we set mtotalitems as 0.
    mTotalItems = 0;
    GomusApplication.sPreferenceManager.setValue(PENDENT_DOWNLOAD_ITEMS, 0);

}

DownloadRepositoryImpl

private <T extends RealmObject> void downloadData(
        BaseDao<T> dao,
        List<T> data,
        Func1<T, Long> id,
        Func1<T, String> url,
        Action1<Result<Void>> resultAction,
        Action2<Result<T>, File> updateEntity,
        Action1<List<File>> onDownloadFinished) {

    //long d = Long.parseLong(null);
    log(Log.DEBUG, TAG, "downloadData Thread.currentThread().getName() " + Thread.currentThread().getName());

    mCurrentDownloadSubscription = Observable.from(data)
            //.observeOn(Schedulers.io())
            .subscribeOn(Schedulers.io())
            .flatMap(song -> downloadAndSaveData(url.call(song), id.call(song)), 2)
            .map(file -> {
                findEntity(dao, Long.parseLong(file == null ? "-1" : file.getName()),
                        resultAction, tResult -> updateEntity.call(tResult, file));
                log(Log.DEBUG, TAG, "map downloadData Thread.currentThread().getName() " + Thread.currentThread().getName());

                return file;
            })
            .toList()
            //.subscribe(onDownloadFinished, err -> onDownloadError(err, resultAction));
            .subscribe(onDownloadFinished, err -> onDownloadError(err, resultAction));
}

DownloadRepositoryImpl

private <T extends RealmObject> void findEntity(BaseDao<T> dao, long id,
                                                Action1<Result<Void>> resultAction,
                                                Action1<Result<T>> result) {
    log(Log.DEBUG, TAG, "Searching for database entity with id " + id + " to update download status ");
    dao.find(query -> query.equalTo("id", id), listResult -> {
        if (listResult.isSuccess) {

            Gson gson = new Gson();
            String resultItem = gson.toJson(listResult.data);
            log(Log.DEBUG, TAG, "Entity with id " + id + " found: " + resultItem);
            if(listResult.data.size()>0)
                result.call(Result.getData(listResult.data.get(0)));
            else {
                log(Log.DEBUG, TAG, "Result is null " + id + " found: ");
                result.call(Result.getData(null));
            }
        } else {
            mHasErrors = true;
            resultAction.call(Result.getError(listResult.error));
        }
    });
}

DownloadRepositoryImpl

private Observable<File> downloadAndSaveData(String url, long id) {
    log(Log.DEBUG,TAG, "Starting download of file at url " + url);
    log(Log.DEBUG, TAG, "downloadAndSaveData Thread.currentThread().getName() " + Thread.currentThread().getName());

    if(url==null)
        url = "";

    return mWebService.downloadData(url)
            .subscribeOn(Schedulers.io())
            //.observeOn(AndroidSchedulers.mainThread())
            //.observeOn(Schedulers.io())
            .flatMap(responseBodyResponse -> onSaveFileToDisk(responseBodyResponse, id));
            //.compose(RxJavaUtils.applySchedulers(false));

}

DownloadWebService

public interface DownloadWebService {
    @Streaming
    @GET
    Observable<Response<ResponseBody>> downloadData(@Url String url);
}

RemoteDataModule

@Provides
@Singleton
DownloadWebService provideDownloadWebService(ServiceFactory factory) {
    return factory.createService(DownloadWebService.class);
}

DownloadRepositoryImpl

private Observable<File> onSaveFileToDisk(Response<ResponseBody> responseBodyResponse, long id) {
    log(Log.DEBUG, TAG, "onSaveFileToDisk Thread.currentThread().getName() " + Thread.currentThread().getName());

    return mLocalStorageProvider
            .saveFromResponse(responseBodyResponse, String.valueOf(id))
            .subscribeOn(Schedulers.io());
            //.observeOn(AndroidSchedulers.mainThread());
}

LocalStorageProviderImpl

@Override
public Observable<File> saveFromResponse(Response<ResponseBody> responseBodyResponse, String fileName) {

    return Observable.defer( new Func0<Observable<File>>()  {
        @Override
        public Observable<File> call() {

            log(Log.DEBUG, TAG, "call Thread.currentThread().getName() " + Thread.currentThread().getName());

            try {
                log(Log.DEBUG, TAG, "File download concluded, saving file from url " +
                        responseBodyResponse.raw().request().url().toString() + " to disk");
                File file = null;
                if(responseBodyResponse.body() != null)
                {
                    file = new File(GomusApplication.getInstance().getFilesDir(), fileName);
                    BufferedSink sink = Okio.buffer(Okio.sink(file));
                    sink.writeAll(responseBodyResponse.body().source());
                    sink.close();
                }
                return Observable.just(file);

                //subscriber.onNext(file);
                //subscriber.onCompleted();
                //return file;

            } catch (IOException e) {
                e.printStackTrace();
                return Observable.error(e);
                //subscriber.onError(e);
            }

        }

    });
}

You remember the first call :

public void startDownload() {
    mInteractor.startDownload(DownloadContentViewModel.this::downloadResult);
    log(Log.DEBUG, TAG, "Thread.currentThread().getName() " + Thread.currentThread().getName());
}

As a result it calls the downloadResult method which is:

DownloadContentViewModel

private void downloadResult(Result<Void> voidResult) {

    if (voidResult.isSuccess) {
        log(Log.DEBUG, TAG, "downloadResult Thread.currentThread().getName() " + Thread.currentThread().getName());

        log(Log.DEBUG, TAG, "downloadResult isSuccess");

        downloadSuccess.set(true);
        //mActivity.setContentView(R.layout.download_success);
        mActivity.runOnUiThread(new Runnable() {

            @Override
            public void run() {
                log(Log.DEBUG, TAG, "runOnUiThread Thread.currentThread().getName() " + Thread.currentThread().getName());

                ((DownloadContentActivity) mActivity).inflateDownloadSuccessLayout();

            }
        });

        getViewState().onNext(ViewState.success());
        GomusApplication.getInstance().setInitialDownloadComplete();
        initTimerDownloadFinished();

    } else {
        log(Log.DEBUG, TAG, "downloadResult errorr");
        log(Log.DEBUG, TAG, "downloadResulterr Thread.currentThread().getName() " + Thread.currentThread().getName());

        downloadFail.set(true);
        downloadSuccess.set(false);
        mActivity.runOnUiThread(new Runnable() {
            @Override
            public void run() {
                log(Log.DEBUG, TAG, "downloadResulterr runOnUiThread Thread.currentThread().getName() " + Thread.currentThread().getName());

                ((DownloadContentActivity)mActivity).inflateDownloadFailedLayout();

            }
        });
        getViewState().onNext(ViewState.error(voidResult.error));
    }
}

DownloadContentViewModel

private void initTimerDownloadFinished() {
    log(Log.DEBUG, TAG, "initTimerDownloadFinished()");

    mDownloadTimerHandler.postDelayed(this::okButton, 10000);
}

I want some help to find out what could be the reason of the ANR dialog in this main thread.

Thanks in advance.

Allow the ANR to kill the app and look in the logs for the process stack dump. It will point you in the right direction. — Larry Schiefer, Nov 27 '19 at 16:53
Waov thank you so much. To do that I need to choose the close the app choice right? — Hilal, Nov 27 '19 at 17:39
Okay I chose the Close app button and actually I was expecting it would print the stacktrace however it printed the last logs only. I think you meant that too. However I am not sure if that was the problem or not. I will add the last log lines when I killed the application to my post. — Hilal, Nov 27 '19 at 18:41
Yes, once you touch "Close App" it will kill the app and it will show the stack dump with some details about the ANR. If you are looking at it in Android Studio, be sure you turn off the logcat filters, otherwise you can miss the logs about ANR as they come from the system rather than your app's process. — Larry Schiefer, Nov 27 '19 at 18:59
Actually I could not see error lines but I see that the http response is a little late. Sometimes thousands of ms. I suspect that is the reason. — Hilal, Nov 27 '19 at 19:08
It's possible that something you've done in your main thread is causing this if it is waiting on something from the http response. It's hard to say without seeing code. But, you won't be able to do the actual http request on the main thread as the OS will prevent all network operations on the main thread by throwing an exception. — Larry Schiefer, Nov 27 '19 at 19:12
@LarrySchiefer Yeah probably the main thread is waiting for a response however how could I solve this, I need to see the result before I inflate the layout. — Hilal, Nov 27 '19 at 19:58
Sounds like a case for using a `RecyclerView` or a pretty generic layout then enable UI components based on the response. You definitely do not want to hold up the main thread waiting for a response from a network service. — Larry Schiefer, Nov 27 '19 at 20:14
@LarrySchiefer The second one, I use the same activity for 3 different layouts. When the download is done, I will show the success page, when the download is failed I will inflate the fail page and during the download I use another layout. I only inflate them according to the result. What should I do ? Should I create different fragments? — Hilal, Nov 27 '19 at 20:16
Yeah, this sounds like you need to break things up into separate activities or fragments. Or, use a single layout and just enable/disable views as needed. Inflation is _very_ expensive in terms of processing time/speed. Couple that with blocking waiting for some kind of network response and you'll hit ANR more often than not. — Larry Schiefer, Nov 27 '19 at 20:56
@LarrySchiefer Actually it was like that before but I separated them into 3 layouts to avoid inflating every time. Actually I thought that the thing that I suspect would not be the problem because the action result of the background thread is calling the inflating. So it should not block the UI I guess, right? — Hilal, Nov 28 '19 at 11:50
There's no way to tell without seeing all of the code involved. — Larry Schiefer, Nov 30 '19 at 01:02
@LarrySchiefer I tried to add the related parts. I hope it is not so messy. I am waiting for your help. Can you tell me if there is an inconvenience that would have caused the ANR pop-up. Thanks in advance. — Hilal, Dec 02 '19 at 14:37
I'd recommend providing a link to github (even a gist) of all the code involved. It's difficult to see how it all interacts, etc. with snippets like this. — Larry Schiefer, Dec 02 '19 at 20:37
Unfortunately I am not able to do that since the project is private. However those places are the ones that are related and the ones that I am suspected. — Hilal, Dec 02 '19 at 21:13
Without seeing exactly where things are kicked off and handled in lifecycle callbacks, there's not much anyone can do to help. You should see a logcat stack trace when the ANR kills the app which will point you in the right direction. The other thing I'd recommend is simplifying the approach. This code is rather complicated. Cascading Rx handling and mixing with `AsyncTask` plus posting things to handlers is asking for trouble. — Larry Schiefer, Dec 03 '19 at 13:30
try using systrace and also if you haven't already please refer the traces.txt — Mangesh Pawar, Dec 06 '19 at 10:35
Traces.txt will be auto generated after an app experiences a ANR. You will find it in /data/anr/traces.txt inside shell. The file that you are referring to is .trace generated via studio, well that is also useful but I suggest to refer and post the trace.txt here. — Mangesh Pawar, Dec 09 '19 at 05:11
@MangeshPawar I think I cannot access the traces.txt file without root access. I have an android tv box which is already rooted, and when I run the cat traces.txt it shows nothing. I think that means it is empty? Also the box does not show the pop-up but I did not fix that so I do not know. — Hilal, Dec 09 '19 at 15:29
@MangeshPawar you may see the traces.txt file through this link => https://gofile.io/?c=BKXCJ2 — Hilal, Dec 09 '19 at 19:57
@MangeshPawar I have `- waiting to lock an unknown object` inside `"HeapTaskDaemon" daemon prio=5 tid=8 Blocked` . What does it mean can someone help? — Hilal, Dec 10 '19 at 13:45

score 0 · Accepted Answer · answered Dec 27 '19 at 15:56

Finally I have found the problem which was nothing to do about the codes that I shared.

In the project a service is started but did not set the notification like startForeground(ID, notification). It was not showing in the logs. When I choose the Information level logs I saw the cause which was

E/ActivityManager: ANR in PID: 6516 Reason: Context.startForegroundService() did not then call Service.startForeground() It was an unnecessary service call so I commented that and the ANR dialog is disappeared.

Find out the reason of ANR using Android Profiler

You may see the traces.txt file via this link => gofile.io/?c=BKXCJ2

1 Answers1