Android: handler messages delayed at the end of a workflow

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

The purpose of the application is to test the NFC chip (ISO15693) by sending a list of predefined commands. Therefore, sending commands is performed by a stream, 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);        
    }
}

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 (, )

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);                

    }
}

, , "handleMessage" "onTestResult" , "sendCommand". , , , , . , , , " ​​" " ..." .

" 34 ! ". , , , 34 . , , " " (id 69595), . (100-1000 ) , , , "Frames".

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

, . , . , .

, , , , . , .

+4
1

synchronized _runTest(). Application, , , , _runTest(), for.

, Application, , . runTest() _runTest() (buildTest(testMap) , , _runTest(), ?).

+2

All Articles