[SOLVED] Find out the reason of ANR using Android Profiler

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.