Android: Handler's messages delayed at end of worker thread

Question

I'm using a thread, inside a service, which do some heavy processing and I want to update the GUI (activity) during this processing. To do this I'm sending messages from thread to a handler and I update the GUI from the handler. But the problem is that the messages are received by the handler only when the worker thread is terminated, as if the message queue was blocked. The reason I used a service is because the process should continue even if the application is not displayed.

The application goal is to test a NFC chip (ISO15693) by sending a list of predefined commands. So sending commands is done by thread, and for each command the result is sent to the handler.

Here is my code :

Application

public class ISO15693Application extends Application {
...
    //Handler receiving messages from Worker thread
    final RunTestHandler runTestHandler = new RunTestHandler(ISO15693Application.this);    
    static class RunTestHandler extends Handler {
        //Avoid leak with handler        
        //See http://stackoverflow.com/questions/11407943/this-handler-class-should-be-static-or-leaks-might-occur-incominghandler
        private final WeakReference<ISO15693Application> mApplication; 

        RunTestHandler(ISO15693Application isoApp) {
            mApplication = new WeakReference<ISO15693Application>(isoApp);
        }

        @Override
        public void handleMessage(Message msg) {
            // TODO Auto-generated method stub
            super.handleMessage(msg);

            ISO15693Application isoApp = mApplication.get();

            switch(msg.what){
            case MSG_TEST_RESULT:
                NfcVResponse r = (NfcVResponse) msg.obj;
                if(r != null){
                    Log.i(TAG, "handleMessage Thread id : " + Thread.currentThread().getId());
                    isoApp.onTestResult((NfcVResponse) msg.obj, msg.arg1);
                }                    
                break;

            case MSG_TEST_STARTED:
                isoApp.onTestStarted(msg.arg1);
                break;
            case MSG_TEST_TERMINATED:
                isoApp.onTestTerminated();
                break;
            case MSG_ABORTED:
                isoApp.onTestAborted();
                break;

            }
        }
    }


    public void onTestResult(NfcVResponse response, int currentCommand) {        
        Log.i(TAG, "onTestResult. Command: " + response.getCommand().toString() 
                + " Status: " + response.getStatus());

        if(testResultCallback != null){
            testResultCallback.onTestResult(response);
        }
    }

    //Called when user click on "Run" button
    public synchronized void runTest(HashMap<Integer, List<Byte>> testMap){

        this.testMap = testMap;        

        //Start last test result activity
        Intent intent = new Intent(getApplicationContext(), TestResultsActivity.class);
        intent.setAction(ISO15693Application.INTENT_ACTION_TEST_STARTED);
        intent.setFlags(Intent.FLAG_ACTIVITY_NEW_TASK);
        startActivity(intent);

        //Start service responsible to run the test.
        runTestHandler.postDelayed(new Runnable() {            
            @Override
            public void run() {
                startTestService();                
            }
        }, 500);

    }

    /*
     * This function will be called by ISO15693Service.Runner to run the test in another thread. 
     * Messages are sent to runTestHandler to indicate start, progress and end .  
     */
    public synchronized void _runTest() {

        boolean tagLost = false;
        commandList = buildTest(testMap);

        int total = commandList.size();
        Message startMsg = new Message();
        startMsg.what = MSG_TEST_STARTED;
        startMsg.arg1 = total;
        runTestHandler.sendMessage(startMsg);

        Log.d(TAG, "Start test Thread id: " + Thread.currentThread().getId());

        for(int index = 0;index < total; index++){
            NfcVCommand cmd = commandList.get(index);
            NfcVResponse response = NfcVHelper.sendCommand(getNfcV(), cmd);

            switch(response.getStatus()){
            case NfcHelper.NFC_STATUS_OK:
                Log.i(TAG, "Command sent successfully");
                break;
            case NfcHelper.NFC_STATUS_NO_TAG:
                //Tag has been lost, try to reconnect
                Log.i(TAG, "Tag has been lost, reconnect");
                ...
                break;
            case NfcHelper.NFC_STATUS_ERROR:                
            default:
                Log.i(TAG, "Error when sent command " + response.getResponseString());
                break;
            }

            Message msg = new Message();        
            msg.what = MSG_TEST_RESULT;
            msg.arg1 = index;
            msg.arg2 = total;
            msg.obj = response;
            //Update UI with last command result            
            runTestHandler.sendMessage(msg);

            //Even if waiting a short moment to let the message queue processing
            //messages are handled only when the worker thread ends.
            //The only difference is in the log message : 
            //I/Choreographer(26709): Skipped 34 frames!  The application may be doing too much work on its main thread.
            //The number of Skipped frams is bigger according to time waited. 
            /*try {
                Thread.sleep(100);
            } catch (InterruptedException e1) {                
            }*/

            //Check tag lost and user cancellation
            ...
        }

        //Add results to db
        ...        
        runTestHandler.sendEmptyMessage(MSG_TEST_TERMINATED);        
    }
}

Service

public class ISO15693Service extends Service {

    @Override
    public void onCreate() {
        Log.d(TAG, "onCreate");
        //Create updater thread
        this.testRunner = null;
        //get application to access preferences
        isoApp =  (ISO15693Application) getApplication();

        super.onCreate();
    }

    @Override
    public void onDestroy() {

        super.onDestroy();
        Log.d(TAG, "onDestroy");

        if(this.testRunner != null){        
            this.testRunner.interrupt();
            this.testRunner = null;
        }
        this.runFlag = false;
        this.isoApp.setTestRunning(false);
    }

    @Override
    public int onStartCommand(Intent intent, int flags, int startId) {        
        Log.d(TAG, "onStartCommand");
        //not already running ? 
        if(!this.runFlag){
            try{
                this.testRunner = new Runner();
                this.runFlag = true;
                this.isoApp.setTestRunning(true);    
                this.testRunner.start();                            
            } catch(IllegalThreadStateException e){                
            }
        }        
        return super.onStartCommand(intent, flags, startId);
    }


    @Override
    public IBinder onBind(Intent intent) {
        // TODO Auto-generated method stub
        return null;
    }

    private class Runner extends Thread{

        Runner(){
            super("Runner class");
        }

        @Override
        public void run() {
            super.run();
            ISO15693Service is = ISO15693Service.this;
            ISO15693Application isoApp = (ISO15693Application) is.getApplication();

            Log.d(TAG, "Runner.run() Thread id: " + Thread.currentThread().getId());

            isoApp._runTest();
            is.runFlag = false;
            isoApp.setTestRunning(false);            
        }
    }

}

TestResultActivity (Activity showing results)

public class TestResultsActivity extends ISO15693BaseActivity
implements ISO15693Application.TestResultCallback{

    ...

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

        mainLayout = (LinearLayout) findViewById(R.id.resultLayout);
        progressBar = (ProgressBar) findViewById(R.id.progressBar);
        ...
    }    

    @Override
    public void onResume() {    
        super.onResume();
        isoApp.setTestResultCallback(this);
    }

    @Override
    public void onPause() {
        super.onPause();
        //Disable callback if activity is not at foreground
        isoApp.setTestResultCallback(null);
    }

    //Add command result to the main layout 
    @Override
    public void onTestResult(final NfcVResponse response) {
        if(mainLayout != null){
            LayoutParams params = new LayoutParams(LayoutParams.MATCH_PARENT, LayoutParams.WRAP_CONTENT);
            TestResultView rv = new TestResultView(TestResultsActivity.this, response);
            mainLayout.addView(rv, params);                    
        }
        progressBar.setProgress(progress++);

    }

    @Override
    public void onTestStarted() {
        Log.i(TAG, "onTestStarted");

        Log.d(TAG, "GUI Thread id: " + Thread.currentThread().getId());
        mainLayout.removeAllViews();
        progress = 0;
        progressBar.setVisibility(View.VISIBLE);
        progressBar.setMax(isoApp.getTestInfo().nbCommands);        
    }

    @Override
    public void onTestTerminated() {
        Log.i(TAG, "onTestTerminated");        
        progressBar.setVisibility(View.GONE);                

    }
}

Here is the log, we can see that "handleMessage" and "onTestResult" are called only at the end, after the last "sendCommand" call. But they should be processed directly, or maybe with a small delay, but not delayed as it is. Note that the moment where a message is sent to the handler corresponds to the lines "Command sent successfully" or "Error when sent command ..." in the log.

There is also the message "Skipped 34 frames! The application may be doing too much work on its main thread." I think the problem is here and this message indicates that the GUI has been frozen during 34 frames. But I don't understand why because all the "heavy processing" is done in another thread (id 69595) than GUI thread. I also tried to wait (100-1000ms) between each command processing, but this changes nothing, except that more "Frames" are skipped.

12-16 10:43:19.600: I/ISO15693Application(26709): Activity TestResultsActivity created
12-16 10:43:19.615: D/TestResultsActivity(26709): GUI Thread id: 1
12-16 10:43:20.145: D/ISO15693Service(26709): onCreate
12-16 10:43:20.145: D/ISO15693Service(26709): onStartCommand
12-16 10:43:20.145: D/ISO15693Application(26709): Build Test Thread id: 69595
12-16 10:43:20.150: I/ISO15693Application(26709): Test started: 8 commands
12-16 10:43:20.150: I/TestResultsActivity(26709): onTestStarted
12-16 10:43:20.150: D/TestResultsActivity(26709): GUI Thread id: 1
12-16 10:43:20.150: D/ISO15693Application(26709): Start test Thread id: 69595
12-16 10:43:20.150: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.150: D/NfcVHelper(26709): Send command : 00 20 10 
12-16 10:43:20.185: D/NfcVHelper(26709): Response : 00 5a a5 5a a5 
12-16 10:43:20.185: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.185: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.185: D/NfcVHelper(26709): Send command : 00 21 10 5a a5 5a a5 
12-16 10:43:20.245: D/NfcVHelper(26709): Response : 00 
12-16 10:43:20.245: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.245: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.245: D/NfcVHelper(26709): Send command : 00 23 01 02 
12-16 10:43:20.290: D/NfcVHelper(26709): Response : 00 00 00 00 00 00 00 00 00 00 00 00 00 
12-16 10:43:20.290: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.290: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.290: D/NfcVHelper(26709): Send command : 00 27 af 
12-16 10:43:20.330: D/NfcVHelper(26709): Response : 00 
12-16 10:43:20.330: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.330: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.330: D/NfcVHelper(26709): Send command : 00 29 d5 
12-16 10:43:20.375: D/NfcVHelper(26709): Response : 00 
12-16 10:43:20.375: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.375: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.375: D/NfcVHelper(26709): Send command : 00 2b 
12-16 10:43:20.410: D/NfcVHelper(26709): Response : 00 xx xx xx xx xx xx xx xx xx xx xx xx xx xx 
12-16 10:43:20.410: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.410: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.410: D/NfcVHelper(26709): Send command : 00 2c 00 00 
12-16 10:43:20.450: D/NfcVHelper(26709): Response : 00 01 
12-16 10:43:20.450: I/ISO15693Application(26709): Command sent successfully
12-16 10:43:20.450: D/NfcVHelper(26709): SendCommand Thread id: 69595
12-16 10:43:20.450: D/NfcVHelper(26709): Send command : 00 a5 16 
12-16 10:43:20.505: W/System.err(26709): android.nfc.TagLostException: Tag was lost.
12-16 10:43:20.505: W/System.err(26709):    at android.nfc.TransceiveResult.getResponseOrThrow(TransceiveResult.java:48)
12-16 10:43:20.505: W/System.err(26709):    at android.nfc.tech.BasicTagTechnology.transceive(BasicTagTechnology.java:151)
12-16 10:43:20.505: W/System.err(26709):    at android.nfc.tech.NfcV.transceive(NfcV.java:115)
12-16 10:43:20.505: W/System.err(26709):    at em.marin.nfc.NfcVHelper.sendCommand(NfcVHelper.java:283)
12-16 10:43:20.505: W/System.err(26709):    at em.marin.iso15693test.ISO15693Application._runTest(ISO15693Application.java:447)
12-16 10:43:20.505: W/System.err(26709):    at em.marin.iso15693test.ISO15693Service$Runner.run(ISO15693Service.java:88)
12-16 10:43:20.505: I/ISO15693Application(26709): Error when sent command IO Exception occured during transmission of the command
12-16 10:43:20.730: I/Choreographer(26709): Skipped 34 frames!  The application may be doing too much work on its main thread.
12-16 10:43:20.795: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.795: I/ISO15693Application(26709): onTestResult. Command: Read Single Block Status: 0
12-16 10:43:20.820: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.820: I/ISO15693Application(26709): onTestResult. Command: Write Single Block Status: 0
12-16 10:43:20.830: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.830: I/ISO15693Application(26709): onTestResult. Command: Read Multiple Blocks Status: 0
12-16 10:43:20.845: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.845: I/ISO15693Application(26709): onTestResult. Command: Write AFI Status: 0
12-16 10:43:20.855: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.855: I/ISO15693Application(26709): onTestResult. Command: Write DSFI Status: 0
12-16 10:43:20.865: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.865: I/ISO15693Application(26709): onTestResult. Command: Get System Information Status: 0
12-16 10:43:20.875: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.875: I/ISO15693Application(26709): onTestResult. Command: Get Multiple Block Security Status Status: 0
12-16 10:43:20.885: I/ISO15693Application(26709): handleMessage Thread id : 1
12-16 10:43:20.885: I/ISO15693Application(26709): onTestResult. Command: Read Sig Status: 1
12-16 10:43:20.890: I/ISO15693Application(26709): Test has been terminated successfully
12-16 10:43:20.890: I/TestResultsActivity(26709): onTestTerminated
12-16 10:43:20.955: D/ISO15693Service(26709): onDestroy

I hope my explanations are clear. Architecture of the application can seem strange, but I tried to separate maximum the GUI and processing. Of course any suggestions for improvements or better practice are welcome.

I searched a long time on this forum and the others to find a similar issue but I didn't find so I apologize in advance if this question has already been asked. Sorry also for my english, that's not my native language.

you can use the Broadcast receiver in the Activity to update the UI, use the service to trigger the Receiver — wolverine
Does this mean that this is an expected behavior when using Handlers ? I really want to understand what is going wrong in my code. Anyway thanks for solution proposal, I will try. But I have to find a solution to pass a NfcVResponse object to the broadcast message, this was the reason why I chosse Handler instead of Broadcast messages. — Gojir4
Very strange, I tried with BroadcastReceiver and it has worked only the first time I launched, and then now I have the same behavior that with handler... — Gojir4
Try removing the synchronized keyword from _runTest() and see how it goes. — user
Yes, it works after removing 'synchronnized', thank you Luksprog. Can you add this as an answer, so I can accept it. Can you give an explanation about this behavior ? Seems I don't understand how 'synchronized' works. — Gojir4

user user · Accepted Answer · 2013-12-18T10:37:53

Remove the synchronized keyword from the _runTest() method. You're synchronizing on the whole Application object which seems to block the UI thread until you finish the _runTest() method, bulking up all the sent messages through the handler in the for loop.

The methods that you have in the code for the Application class you posted don't need to be synchronized. This goes for runTest() and especially for _runTest()(buildTest(testMap) it's a private method, most likely called only from _runTest(), right?).

Android: Handler's messages delayed at end of worker thread

1 Answers