App dies on startup

Question

When I start my app, I start an AsyncTask to do some downloading. This can take a while.
When that thread is downloading the data, I am already listening for location updates. When I receive a new location, I start a new AsyncTask to do some processing. However, this class depends on the downloaded data, so it has to wait until the downloading is done:

public void setLocation(Location location) throws IOException {
    Logger.log("New location - calculating nearest stations");
    if (!initialStationsRead) {
        Logger.log("Location update waiting for stations to be read");
        while (!initialStationsRead)
            ;
        Logger.log("Location update done waiting");
    }
    /* Do the processing */
}

The first thread sets initialStationsRead to true when it's done, so the second thread can pick up after that. This all works fine on my test devices.

However, I received an email from a user telling me that the app won't start. The loading screen appeared, and after 10-12 seconds disappeared without a warning. He uses a HTC One S.

This is the logcat he sent me:

07-05 22:11:04.938: W/dalvikvm(19961): threadid=2: spin on suspend #2 threadid=11 (pcf=1)
07-05 22:11:04.938: I/dalvikvm(19961): "GC" daemon prio=5 tid=2 RUNNABLE
07-05 22:11:04.938: I/dalvikvm(19961):   | group="system" sCount=0 dsCount=0 obj=0x40d5c580 self=0x1669ae8
07-05 22:11:04.938: I/dalvikvm(19961):   | sysTid=19965 nice=0 sched=0/0 cgrp=default handle=21931384
07-05 22:11:04.938: I/dalvikvm(19961):   | schedstat=( 0 0 0 ) utm=2 stm=0 core=1
07-05 22:11:04.938: I/dalvikvm(19961):   at dalvik.system.NativeStart.run(Native Method)
07-05 22:11:04.938: I/dalvikvm(19961): "AsyncTask #3" prio=5 tid=11 RUNNABLE JIT
07-05 22:11:04.938: I/dalvikvm(19961):   | group="main" sCount=1 dsCount=0 obj=0x40f90588 self=0x1b35b00
07-05 22:11:04.938: I/dalvikvm(19961):   | sysTid=19991 nice=0 sched=0/0 cgrp=default handle=29193008
07-05 22:11:04.938: I/dalvikvm(19961):   | schedstat=( 0 0 0 ) utm=287 stm=1 core=1
07-05 22:11:04.938: I/dalvikvm(19961):   at com.busybits.treinverkeer.data.Data.setLocation(Data.java:~102)
07-05 22:11:04.938: I/dalvikvm(19961):   at com.busybits.treinverkeer.TreinVerkeer$SetLocationAsyncTask.doInBackground(TreinVerkeer.java:408)
07-05 22:11:04.938: I/dalvikvm(19961):   at com.busybits.treinverkeer.TreinVerkeer$SetLocationAsyncTask.doInBackground(TreinVerkeer.java:1)
07-05 22:11:04.938: I/dalvikvm(19961):   at android.os.AsyncTask$2.call(AsyncTask.java:264)
07-05 22:11:04.938: I/dalvikvm(19961):   at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
07-05 22:11:04.938: I/dalvikvm(19961):   at java.util.concurrent.FutureTask.run(FutureTask.java:137)
07-05 22:11:04.938: I/dalvikvm(19961):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
07-05 22:11:04.938: I/dalvikvm(19961):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
07-05 22:11:04.938: I/dalvikvm(19961):   at java.lang.Thread.run(Thread.java:864)
07-05 22:11:05.629: D/WifiStateMachine(436): fetchRssiAndLinkSpeedNative RSSI = -32
07-05 22:11:05.689: W/dalvikvm(19961): threadid=2: spin on suspend #3 threadid=11 (pcf=1)
07-05 22:11:05.689: I/dalvikvm(19961): "GC" daemon prio=5 tid=2 RUNNABLE
07-05 22:11:05.689: I/dalvikvm(19961):   | group="system" sCount=0 dsCount=0 obj=0x40d5c580 self=0x1669ae8
07-05 22:11:05.689: I/dalvikvm(19961):   | sysTid=19965 nice=0 sched=0/0 cgrp=default handle=21931384
07-05 22:11:05.689: I/dalvikvm(19961):   | schedstat=( 0 0 0 ) utm=2 stm=0 core=1
07-05 22:11:05.689: I/dalvikvm(19961):   at dalvik.system.NativeStart.run(Native Method)
07-05 22:11:05.689: I/dalvikvm(19961): "AsyncTask #3" prio=5 tid=11 RUNNABLE JIT
07-05 22:11:05.689: I/dalvikvm(19961):   | group="main" sCount=1 dsCount=0 obj=0x40f90588 self=0x1b35b00
07-05 22:11:05.689: I/dalvikvm(19961):   | sysTid=19991 nice=0 sched=0/0 cgrp=default handle=29193008
07-05 22:11:05.689: I/dalvikvm(19961):   | schedstat=( 0 0 0 ) utm=362 stm=1 core=1
07-05 22:11:05.689: I/dalvikvm(19961):   at com.busybits.treinverkeer.data.Data.setLocation(Data.java:~102)
07-05 22:11:05.689: I/dalvikvm(19961):   at com.busybits.treinverkeer.TreinVerkeer$SetLocationAsyncTask.doInBackground(TreinVerkeer.java:408)
07-05 22:11:05.689: I/dalvikvm(19961):   at com.busybits.treinverkeer.TreinVerkeer$SetLocationAsyncTask.doInBackground(TreinVerkeer.java:1)
07-05 22:11:05.689: I/dalvikvm(19961):   at android.os.AsyncTask$2.call(AsyncTask.java:264)
07-05 22:11:05.689: I/dalvikvm(19961):   at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
07-05 22:11:05.689: I/dalvikvm(19961):   at java.util.concurrent.FutureTask.run(FutureTask.java:137)
07-05 22:11:05.689: I/dalvikvm(19961):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
07-05 22:11:05.689: I/dalvikvm(19961):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
07-05 22:11:05.689: I/dalvikvm(19961):   at java.lang.Thread.run(Thread.java:864)
07-05 22:11:05.719: D/skia(1004): AndroidImageRef[ 0x2438190 ] releasePixel fail as lockCount=1
07-05 22:11:06.439: W/dalvikvm(19961): threadid=2: spin on suspend #4 threadid=11 (pcf=1)
07-05 22:11:06.439: I/dalvikvm(19961): "GC" daemon prio=5 tid=2 RUNNABLE
07-05 22:11:06.439: I/dalvikvm(19961):   | group="system" sCount=0 dsCount=0 obj=0x40d5c580 self=0x1669ae8
07-05 22:11:06.439: I/dalvikvm(19961):   | sysTid=19965 nice=0 sched=0/0 cgrp=default handle=21931384
07-05 22:11:06.439: I/dalvikvm(19961):   | schedstat=( 0 0 0 ) utm=2 stm=0 core=1
07-05 22:11:06.439: I/dalvikvm(19961):   at dalvik.system.NativeStart.run(Native Method)
07-05 22:11:06.439: I/dalvikvm(19961): "AsyncTask #3" prio=5 tid=11 RUNNABLE JIT
07-05 22:11:06.439: I/dalvikvm(19961):   | group="main" sCount=1 dsCount=0 obj=0x40f90588 self=0x1b35b00
07-05 22:11:06.439: I/dalvikvm(19961):   | sysTid=19991 nice=0 sched=0/0 cgrp=default handle=29193008
07-05 22:11:06.439: I/dalvikvm(19961):   | schedstat=( 0 0 0 ) utm=437 stm=1 core=1
07-05 22:11:06.439: I/dalvikvm(19961):   at com.busybits.treinverkeer.data.Data.setLocation(Data.java:~102)
07-05 22:11:06.439: I/dalvikvm(19961):   at com.busybits.treinverkeer.TreinVerkeer$SetLocationAsyncTask.doInBackground(TreinVerkeer.java:408)
07-05 22:11:06.439: I/dalvikvm(19961):   at com.busybits.treinverkeer.TreinVerkeer$SetLocationAsyncTask.doInBackground(TreinVerkeer.java:1)
07-05 22:11:06.439: I/dalvikvm(19961):   at android.os.AsyncTask$2.call(AsyncTask.java:264)
07-05 22:11:06.439: I/dalvikvm(19961):   at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
07-05 22:11:06.439: I/dalvikvm(19961):   at java.util.concurrent.FutureTask.run(FutureTask.java:137)
07-05 22:11:06.439: I/dalvikvm(19961):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
07-05 22:11:06.439: I/dalvikvm(19961):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
07-05 22:11:06.439: I/dalvikvm(19961):   at java.lang.Thread.run(Thread.java:864)

This is repeated x times.

Now, Data.java:102 is the line while(!initialStationsRead), so there must be going something wrong there.

What is happening, and how can I solve this?

Answer 1

The first thread sets initialStationsRead to true when it's done, so the second thread can pick up after that.

Busy loops are evil incarnate. If I had holy water handy, you'd be rather wet right now. :-)

(that also implies that I have really good holy-water throwing aim over long distances, which probably isn't the case)

Java has plenty of options for thread synchronization, and has had them for a decade-plus, from the low-level wait() and notify() on Object to the java.util.concurrent constructs like Semaphore. Pick one and use it, getting rid of the busy loop.

Or, follow Jan-Henk's advice and do the work serially on the same thread, based on a flag.

Any idea though why this happens on his device and not on mine or devices of other people i know?

Well, for starters, the One S is dual-core, and so your threads may actually be running at the same time (one per core). Threading problems will be more likely to surface in multi-core environments.

Also, Angelo's answer -- posted while I was writing this -- is worth noting.

Answer 2

I don't know if that helps but keep in mind that after HoneyComb (Android 3.0) and before Donut (Android 1.6) only one AsyncTask can run simultaneously, since AsyncTask use a thread pool pattern and the default thread pool size on these versions is 1. If you want the AsyncTasks you are using to run simulteneously in these versions of Android, you can use this code executeOnExecutor(Executor, Params...) using the flag THREAD_POOL_EXECUTOR. See this answer of this previous post for more information. Seeing that the user that has an HTC One S device wich runs Android 4.0, maybe this is the source of your problem.