runOnUiThread executes after waiting 30 seconds

Question

I came across an extremely weird behaviour related to code execution on UI thread after server data retrieval.

In onResume, I start a Thread where I wait for some server data fetch to complete and then run ui updates.

But the problem is that runOnUiThread command more often than not only starts executing after a delay of 30 seconds. It happens with some servers, but not with others, as per example below.

Here's the full code in onResume:

 @Override
public void onResume() {

    super.onResume();
    new Thread(new Runnable() {
        @Override
        public void run() {
            try {
                Log.e("TESTUI_1", "");

                String urlname = "https://stackoverflow.com";//runonuithread starts immediately
                //String urlname = "https://cnn.com";//runonuithread waits 30 seconds
                URL url = new URL(urlname);
                Log.e("TESTUI_1", urlname);
                HttpURLConnection connectionCache = (HttpURLConnection) url.openConnection();
                connectionCache.setDoOutput(true);

                connectionCache.setRequestProperty("Content-Type", "application/json");//MAn680
                connectionCache.setRequestMethod("POST");//MAn680
                connectionCache.setRequestProperty("Connection", "close");//MAn1140
                connectionCache.setConnectTimeout(10000);
                connectionCache.setReadTimeout(10000);
                connectionCache.setDoInput(true);//3.9.13
                connectionCache.setUseCaches(false); //3.9.13

                int status = connectionCache.getResponseCode();//3.9.12
                Log.e("TESTUI_status", ""+status);
                InputStream is;

                if (status >= 400) {
                    is = connectionCache.getErrorStream();
                } else {
                    is = connectionCache.getInputStream();
                }
            } catch (Exception e) {
                Log.e("TESTUI_error", e.getLocalizedMessage());
            }
            long when = new Date().getTime();
            Log.e("TESTUI_2", ""+when);
            runOnUiThread(new Runnable() {
                @Override
                public void run() {
                    long delta = new Date().getTime() - when;
                    Log.e("TESTUI_3", ""+delta);
                }
            });
        }
    }).start();


}

Logcat output with cnn.com:

TESTUI_1 E
TESTUI_1 E https://cnn.com
TESTUI_status E 200
TESTUI_2 E 1693556722917
TESTUI_3 E 29643

Logcat output with stackoverflow.com:

TESTUI_1 E
TESTUI_1 E https://stackoverflow.com
TESTUI_status E 200
TESTUI_2 E 1693556962546
TESTUI_3 E 230

Is there anything in the Logcat that I could search for?

Answer 1

runOnUiThread post a message to your main Looper's MessageQueue, whose message is handled one by one.

So it's possible that MessageQueue is full of other message which took long time to process, which will result in long delay before your Runnable executed.

You can verify this by replace runOnUiThread with below code:

// this will insert your Runnable at the front of MessageQueue
new Handler(Looper.getMainLooper()).postAtFrontOfQueue(() -> {
    long delta = new Date().getTime() - start;
    Log.e("TESTUI2", "" + delta);
});

Answer 2

One the weirdest things ever seen in 30 years of software development. The cause of the problem was using elsewhere the deprecated GoogleApiClient for accessing location. This triggered a 30 seconds wait time whenever a server request was sent, but only for some servers. Migrated to FusedLocation and problem disappeared