Databases
StackOverflow2013
Postsdbo
POAndroid: Handler's messages delayed at end of worker thread
 

Note that there are some explanatory texts on larger screens.

plurals
  1. POAndroid: Handler's messages delayed at end of worker thread
    primarykey
    data
    text
    <p>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. </p> <p>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.</p> <p>Here is my code : </p> <p>Application</p> <pre><code>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&lt;ISO15693Application&gt; mApplication; RunTestHandler(ISO15693Application isoApp) { mApplication = new WeakReference&lt;ISO15693Application&gt;(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&lt;Integer, List&lt;Byte&gt;&gt; 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 &lt; 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); } } </code></pre> <p>Service</p> <pre><code>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); } } } </code></pre> <p>TestResultActivity (Activity showing results)</p> <pre><code>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); } } </code></pre> <p>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.</p> <p>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. </p> <pre><code>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 </code></pre> <p>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. </p> <p>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. </p>
    singulars
    1. PO
      singulars
      1. PTAnswer
    1. This table or related slice is empty.
    1. PTQuestion
    1. USGojir4
    1. USGojir4
    plurals
    1. PL
      singulars
      1. LTLinked
    1. This table or related slice is empty.
    1. This table or related slice is empty.
    1. PO
      singulars
      1. PTAnswer
    1. VO
      singulars
      1. POAndroid: Handler's messages delayed at end of worker thread
      1. This table or related slice is empty.
      1. VTUpMod
    2. VO
      singulars
      1. POAndroid: Handler's messages delayed at end of worker thread
      1. This table or related slice is empty.
      1. VTUpMod
    3. VO
      singulars
      1. POAndroid: Handler's messages delayed at end of worker thread
      1. This table or related slice is empty.
      1. VTUpMod
    1. COyou can use the Broadcast receiver in the Activity to update the UI, use the service to trigger the Receiver
      singulars
      1. POAndroid: Handler's messages delayed at end of worker thread
      1. USwolverine
    2. CODoes 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.
      singulars
      1. POAndroid: Handler's messages delayed at end of worker thread
      1. USGojir4
    3. COVery 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...
      singulars
      1. POAndroid: Handler's messages delayed at end of worker thread
      1. USGojir4
 

Querying!

 
Guidance
A row detail

Detail views are divided into sections. All the information in the data section comes from columns in the selected row. The other sections display data from other, related rows.

Related data can be related in a to-one or a to-many fashion. Captions of data related in a to-many fashion link to a list view showing a filtered view of the table.

Try moving around until you find a non-empty to-many entry and click on the label to get to one. You can move back to the root by clicking on the database name in the header.

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload