When are runnables posted in postDelayed actually executed on Android?

Question

There is a piece of code where I use postDelayed and some other code executed on the main thread. I ran it a few times and always saw the following output:

07-13 14:22:18.511 15376-15376/sample1.com.sample_1 D/MainActivity: i = 0

....

07-13 14:22:18.601 15376-15376/sample1.com.sample_1 D/MainActivity: onResume 07-13 14:22:18.601 15376-15376/sample1.com.sample_1 D/MainActivity: postDelayed

As I see from the log output, it doesn't matter that my delay is 50 ms. The message "postDelayed" is typed after about 100 ms (601 - 511 = 90). It looks like the delayed runnable is added to the end of my UI thread's message queue. But anyway, is there any guarantee about when exactly postDelayed is typed? Can it be typed in the middle of the for loop?

package sample1.com.sample_1;

import android.os.Bundle;
import android.os.Handler;
import android.support.v7.app.AppCompatActivity;
import android.util.Log;

public class MainActivity extends AppCompatActivity {


    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);

        new Handler().postDelayed(new Runnable() {
            @Override
            public void run() {
                Log.d("MainActivity", "postDelayed");
            }
        }, 10);
        for (int i = 0; i < 10000; i++) {
            Log.d("MainActivity", "i = " + i);
        }
    }

    @Override
    protected void onResume() {
        Log.d("MainActivity", "onResume");
        super.onResume();

    }
}

Android limits the UI operation in main thread is to prevent the things you want to do. — Harlan, Jul 13 '16 at 12:09

score 2 · Accepted Answer · answered Jul 13 '16 at 13:06

There are logs from other services and applications too, so calculating Handler delay based on the log output will not be correct. Logging mechanism on the Android has its own queue so your message actually might be delayed due to other logs in the queue.

My suggestion would be using System.nanoTime() to calculate the time between Handler delays. As far as I know it gives the most precise timer value.

Lastly to answer your question, no you can not pinpoint the exact time when an action will take place. There are thousands (if not millions) of different conditions which might delay actions of your application, especially if it is an asynchronous action.

Edit: That delay cannot guarantee exactly 50ms delay but it can guarantee "at least" 50ms delay.

Yes, it looks like `postDelayed(r, 10)` guarantees _at least_ 10 ms. Here is an example with nanoTime https://gist.github.com/anonymous/70f301a06959f91b96302d6a6adddd6d — Maksim Dmitriev, Jul 13 '16 at 15:01
07-13 17:58:36.391 30902-30902/sample1.com.sample_1 D/MainActivity: timeHandler = 22583545657183 07-13 17:58:36.281 30902-30902/sample1.com.sample_1 D/MainActivity: beforeTimeHandler = 22583437099224 The diff is 108557959 nanosec = 10 ms (approximately) — Maksim Dmitriev, Jul 13 '16 at 15:05

score 1 · Answer 2 · answered Jul 13 '16 at 13:21

After tracing the code for Handler.postDelay() down, it looks like eventually MessageQueue.enqueueMessage() is called. From the code, it seems to infinitely loop through the message queue till it reaches the end or till the current tasks time is higher than our delay time and then inserts the task in to that position in the queue. What this means is that the queue ahead of where your task is executed is taking very long, you should more of less have your task executed within a few milliseconds of when you want.

I'm guessing that your operations aren't the problem, but rather, the Android is busy on the main thread rendering your UI and other internal jobs which is what is delaying your task. Presumably, executing all the code in onCreate, onStart, onResume on your activity and the classes it extends was queued before your postDelay time + 10ms.

100ms is roughly 6 frames, so it could just be the time taken to display your activity's UI, try executing your postDelay on a button click instead, I believe time will be a lot more predictable then since the UI and Activity are not being setup or torn down.

07-13 17:49:45.781 14332-14332/sample1.com.sample_1 D/MainActivity: i = 0 ..... 07-13 17:49:45.871 14332-14332/sample1.com.sample_1 D/MainActivity: postDelayed It looks like moving the code to a button click doesn't make any difference — Maksim Dmitriev, Jul 13 '16 at 14:53

score 0 · Answer 3 · answered Jul 13 '16 at 12:51

use post() actually call sendMessageDelayed(getPostMessage(r), 0), and postDelayed() will call sendMessageDelayed(getPostMessage(r), delayMillis), they are similar.

the post...() methods will eventually call queue.enqueueMessage, different at the when param, it decides where the msg will be inserted into the message queue. you can change the msg in the queue, but can't interrupt the msg has run.

When are runnables posted in postDelayed actually executed on Android?

3 Answers3