3

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?

nhaarman
  • 98,571
  • 55
  • 246
  • 278
  • 2
    Instead of blocking the setLocation() method until the location data is available, you can try to start the processing of the data after the downloading is finished and there is a location available. Or you can register your location updates after the downloading of the data is done. – Jan-Henk Jul 05 '12 at 21:13
  • I suspect it would be better for the consumer AsyncTask to wait rather than loop infinitely waiting for the station data. Add a Log statement to that loop to observe what is going on. – Rob Kielty Jul 05 '12 at 21:13
  • @Jan-Henk Yes I thought of that whilst writing this question, I could try that indeed. – nhaarman Jul 05 '12 at 21:15
  • Could use a Handler inside the async task to process the messages - say download data, pass it in via handlers into the async task... – t0mm13b Jul 05 '12 at 21:19
  • I've sent the user the version with the suggestion of @Jan-Henk, now I'll just have to wait if this solves the problem. Any idea though why this happens on his device and not on mine or devices of other people i know? – nhaarman Jul 05 '12 at 21:27
  • I am just speculating right now, buty maybe there are a lot of location updates at the user's device, which will lead to a lot of blocked methods, which in turn results in this problem? – Jan-Henk Jul 05 '12 at 21:33
  • I can conclude from the logcat he sent me that is not the case :) – nhaarman Jul 05 '12 at 21:48

2 Answers2

3

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.

CommonsWare
  • 986,068
  • 189
  • 2,389
  • 2,491
  • Actually, I could use some water here, it is hot as hell :) Anyways, like I commented on my question, I've implemented Jan-Henk's suggestion and sent a copy to the user. +1 for the explanation though! I will await a response from the user before accepting an answer. – nhaarman Jul 05 '12 at 21:51
0

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.

Community
  • 1
  • 1
AggelosK
  • 4,313
  • 2
  • 32
  • 37
  • Note that the serialized executor for `execute()` only kicks in if you have `android:targetSdkVersion` set to 13 or higher, and you are running on Android 3.2 or higher. – CommonsWare Jul 05 '12 at 21:35
  • I've indeed tackled that problem already, and already applied the `THREAD_POOL_EXECUTOR` fix. (See this question: http://stackoverflow.com/questions/11229734/disable-use-of-asynctask-using-custom-asynctask) Thanks for thinking along! – nhaarman Jul 05 '12 at 21:53
  • I proposed a solution to your previous question. I don't know if this was what you were looking for. Hope that helps:) – AggelosK Jul 05 '12 at 22:24