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.