ANR for my IntentService

Question

I have an IntentService that creates a new thread and runs a long operation.

    @Override
    protected void onHandleIntent(Intent intent) {
        Log.d(TAG, "onHandleIntent at " + Calendar.getInstance().getTime());
        new Thread() {
            public void run() {
                Process.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND);
                            << A VERY LONG OPERATION == NETWORK + FILESYSTEM etc >>
                };
        }.start();
    }

Even though it is an IntentService, I see ANRs because of this service. According to my understanding IntentService runs on its own thread right?

06-28 02:18:36.751 I/ActivityManager( 1109): START {cmp=x.y.z/.MainActivity} from pid 466                                           
06-28 02:19:56.861 W/ActivityManager( 1109): Timeout executing service: ServiceRecord{41767d48 x.y.z/x.y.a.RefreshService}                                                                                                                                                
06-28 02:19:58.001 E/ActivityManager( 1109): ANR in x.y.z                                                                              
06-28 02:19:58.001 E/ActivityManager( 1109): Reason: Executing service x.y.z/x.y.a.RefreshService              
06-28 02:19:58.001 E/ActivityManager( 1109): Load: 8.5 / 8.16 / 7.52                                                                                       
06-28 02:19:58.001 E/ActivityManager( 1109): CPU usage from 14986ms to 0ms ago:                                                                            
06-28 02:19:58.001 E/ActivityManager( 1109):   117% 2317/mediaserver: 45% user + 71% kernel                                                                
06-28 02:19:58.001 E/ActivityManager( 1109):   57% 2316/debuggerd: 47% user + 10% kernel                                                                   
06-28 02:19:58.001 E/ActivityManager( 1109):   9.5% 1030/PE_Single_CPU: 3.2% user + 6.3% kernel                                                                           
06-28 02:19:58.001 E/ActivityManager( 1109):   0.6% 1109/system_server: 0% user + 0.6% kernel / faults: 1783 minor                                         
06-28 02:19:58.001 E/ActivityManager( 1109):   0.2% 904/yaffs-bg-1: 0% user + 0.2% kernel                                                                  
06-28 02:19:58.001 E/ActivityManager( 1109):   0.1% 901/yaffs-bg-1: 0% user + 0.1% kernel                                                                  
06-28 02:19:58.001 E/ActivityManager( 1109):   0% 1//init: 0% user + 0% kernel                                                                             
06-28 02:19:58.001 E/ActivityManager( 1109):   0% 249/sync_supers: 0% user + 0% kernel                                                                     
06-28 02:19:58.001 E/ActivityManager( 1109):   0% 923/virtualSensors: 0% user + 0% kernel                                                                  
06-28 02:19:58.001 E/ActivityManager( 1109):   0% 1480/com.google.android.gm: 0% user + 0% kernel                                                          
06-28 02:19:58.001 E/ActivityManager( 1109):   0% 1545/com.updater: 0% user + 0% kernel                                                                    
06-28 02:19:58.001 E/ActivityManager( 1109):  +0% 786/logcat: 0% user + 0% kernel                                                                          
06-28 02:19:58.001 E/ActivityManager( 1109): 98% TOTAL: 53% user + 43% kernel + 0.9% softirq                                                               
06-28 02:19:58.001 E/ActivityManager( 1109): CPU usage from 551ms to 1089ms later:                                                                         
06-28 02:19:58.001 E/ActivityManager( 1109):   110% 2317/mediaserver: 41% user + 69% kernel                                                                
06-28 02:19:58.001 E/ActivityManager( 1109):     56% 2451/MRVLFFPlayer: 23% user + 32% kernel                                                              
06-28 02:19:58.001 E/ActivityManager( 1109):     54% 1286/MRVLFFPlayer: 18% user + 36% kernel                                                              
06-28 02:19:58.001 E/ActivityManager( 1109):   67% 2316/debuggerd: 56% user + 10% kernel                                                                   
06-28 02:19:58.001 E/ActivityManager( 1109):   7.4% 1030/PE_Single_CPU: 3.7% user + 3.7% kernel                                                            
06-28 02:19:58.001 E/ActivityManager( 1109):     3.7% 1065/AOUT_HAL_ISR_Ta: 1.8% user + 1.8% kernel                                                        
06-28 02:19:58.001 E/ActivityManager( 1109):     1.8% 1049/TSPMgr_MainTask: 1.8% user + 0% kernel                                                          
06-28 02:19:58.001 E/ActivityManager( 1109):     1.8% 1050/VPP_ISR_Task: 1.8% user + 0% kernel                                                             
06-28 02:19:58.001 E/ActivityManager( 1109):     1.8% 1072/gfxmgr_main_thr: 0% user + 1.8% kernel                                                          
06-28 02:19:58.001 E/ActivityManager( 1109):   5.5% 1109/system_server: 0% user + 5.5% kernel                                                              
06-28 02:19:58.001 E/ActivityManager( 1109):     5.5% 1136/ActivityManager: 0% user + 5.5% kernel                                                          
06-28 02:19:58.001 E/ActivityManager( 1109):   1% 497/kworker/1:1: 0% user + 1% kernel                                                                     
06-28 02:19:58.001 E/ActivityManager( 1109):   1.8% 786/logcat: 0% user + 1.8% kernel / faults: 37 minor                                                   
06-28 02:19:58.001 E/ActivityManager( 1109): 96% TOTAL: 50% user + 45% kernel + 0.9% softirq                                                               
06-28 02:20:36.101 W/ActivityManager( 1109):   Force finishing activity x.y.z/.MainActivity                                         
06-28 02:20:36.141 I/ActivityManager( 1109): Killing ProcessRecord{41623b60 466:x.y.z/10031}: user's request                           
06-28 02:20:36.551 I/WindowManager( 1109): WIN DEATH: Window{41551c38 x.y.z/x.y.z.MainActivity paused=true}     
06-28 02:20:36.551 I/ActivityManager( 1109): Process x.y.z (pid 466) has died.                                                         
06-28 02:20:36.551 W/ActivityManager( 1109): Scheduling restart of crashed service x.y.z/x.y.a.RefreshService in 119400ms

Also, the trace file at /data/anr/traces.txt does not show any thread stack for this service. I can only see the main thread's stack(which is playing videos) and other AsyncTask threads. By anychance, will main thread being busy in setting datasource create the background threads to ANR? Any guidance is welcome.

Here is the stack trace for main thread and refresh thread:

Stack trace:

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x40b06460 self=0x12958
  | sysTid=1248 nice=0 sched=0/0 cgrp=default handle=1074144680
  | schedstat=( 0 0 0 ) utm=100 stm=30 core=0
  at android.media.MediaPlayer._setDataSource(Native Method)
  at android.media.MediaPlayer.setDataSource(MediaPlayer.java:884)
  at android.media.MediaPlayer.setDataSource(MediaPlayer.java:846)
  at android.widget.VideoView.openVideo(VideoView.java:275)
  at android.widget.VideoView.access$2100(VideoView.java:49)
  at android.widget.VideoView$6.surfaceCreated(VideoView.java:520)
  at android.view.SurfaceView.updateWindow(SurfaceView.java:597)
  at android.view.SurfaceView.access$000(SurfaceView.java:86)
  at android.view.SurfaceView$3.onPreDraw(SurfaceView.java:174)
  at android.view.ViewTreeObserver.dispatchOnPreDraw(ViewTreeObserver.java:590)
  at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:1617)
  at android.view.ViewRootImpl.handleMessage(ViewRootImpl.java:2442)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:137)
  at android.app.ActivityThread.main(ActivityThread.java:4424)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:511)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551)
  at dalvik.system.NativeStart.main(Native Method)

"Thread-158" prio=5 tid=20 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x411a38a8 self=0x25af28
  | sysTid=1301 nice=0 sched=0/0 cgrp=default handle=1661840
  | schedstat=( 0 0 0 ) utm=1 stm=3 core=0
  at libcore.io.Posix.recvfromBytes(Native Method)
  at libcore.io.Posix.recvfrom(Posix.java:131)
  at libcore.io.BlockGuardOs.recvfrom(BlockGuardOs.java:164)
  at libcore.io.IoBridge.recvfrom(IoBridge.java:503)
  at java.net.PlainSocketImpl.read(PlainSocketImpl.java:488)
  at java.net.PlainSocketImpl.access$000(PlainSocketImpl.java:46)
  at java.net.PlainSocketImpl$PlainSocketInputStream.read(PlainSocketImpl.java:240)
  at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:103)
  at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:191)
  at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:82)
  at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:174)
  at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:180)
  at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:235)
  at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:259)
  at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:279)
  at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
  at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:428)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:465)
  at x.y.z.c.a.b(SourceFile:597)
  at x.y.z.c.a.a(SourceFile:529)
  at x.y.z.c.a.a(SourceFile:214)
  at x.y.z.c.i.e(SourceFile:290)
  at x.y.z.services.a.run(SourceFile:43)

score 0 · Answer 1 · answered Jun 28 '13 at 05:15

0

I have manipulated the same with While(true),its working fine, From the logs starting the service is having some problem, try to share the other code details.

answered Jun 28 '13 at 05:15

Sarath

1

score 0 · Answer 2 · answered Jun 28 '13 at 06:00

0

Do you bind an Activity to your Service? If so, make sure you only bind to it once. If you bind to it more than once, it will not stop when finishing its job, which may cause your ANR:

See:http://developer.android.com/reference/android/content/Context.html#stopService(android.content.Intent)

answered Jun 28 '13 at 06:00

dors

5,802
8
45
71

Mine is an IntentService, and I launch it via an AlarmManger as pendingIntent. I dont bind at all. – user2488722 Jun 28 '13 at 08:18
Not really, I create a thread right after onHandleIntent. I have attached the stacktrace to my post. – user2488722 Jun 28 '13 at 10:24
Could it be that your threads are accessing the same objects? or maybe you are trying to perform UI actions on your non-UI worker threads? – dors Jun 28 '13 at 14:54
Yes, my threads might access the same objects.But does it matter? I thought we only cant access UI objects. We dont lock any objects with synchronisation as well. – user2488722 Jun 30 '13 at 15:06
Not only UI... What if for instance you are accessing and modifying an array? you need to protect that object in that case – dors Jun 30 '13 at 17:19

ANR for my IntentService

2 Answers2