Hi,
This has been driving me crazy for a week:
My GentleAlarm app has registered a receiver for
"android.intent.action.TIME_TICK" in Activity_Nightmode, updating the
time once per minute on the night display. When an alarm rings, an
Activity_AlarmAlert comes up and starts an alarm service to play some
music in the background. Now one user gets an ANR error. He doesn't
have access to /data/anr/traces.txt but sent me his log file.
The log shows an alarm at 22:52:00, the alarm starts playing fine and
then the ANR error at the bottom of the log (I can't reproduce this on
my device). The log seems to indicate that the system was expecting
GentleAlarm to handle the broadcasted intent but it didn't get a
response in a timely fashion, therefore ANR.
- The time tick must have occurred at 22:52:00. If the time tick event
had been received, there would be a log output. Why didn't it receive
the intent during those almost 15 seconds until the ANR?
- The ANR log seems to indicate that GentleAlarm was busy (79%) but
neither the log file nor my code give me any idea what is has been
doing. It shouldn't be doing anything. It does increase the volume
every few seconds but that takes only a fraction of a second. There
are always gaps where it wasn't doing anything.
- At 22:52:00.796, Activity_Nightmode pauses and unregisters the
TIME_TICK receiver. Still, the ANR occurs 14 seconds later. Why does
it still try to pass the intent on to GentleAlarm even though the
activity has paused?
Any help is greatly appreciated.
Martin
01-29 22:52:00.030 D/GentleAlarm( 4542): Receiver_Alarm: onReceive
2010.01.29 n. Chr. at 22:52:00
01-29 22:52:00.030 D/GentleAlarm( 4542): Alarm: constructor
01-29 22:52:00.030 D/GentleAlarm( 4542): Alarm: reset
01-29 22:52:00.061 D/GentleAlarm( 4542): Alarm:
loadScheduledAlarmAsCurrent => id=2, type=MAIN_ALARM, time=2010.01.29
n. Chr. at 22:52:00, name=Weekend, playAsTest=false, played=false
01-29 22:52:00.061 D/GentleAlarm( 4542): Alarm: loadAlarmDetails
01-29 22:52:00.061 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:00.108 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:00.108 D/GentleAlarm( 4542): Alarm: scheduleNextAlarm
01-29 22:52:00.108 D/GentleAlarm( 4542): Alarm:
isSnoozeOrSafeAlarmScheduled no
01-29 22:52:00.108 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:00.147 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:00.147 D/GentleAlarm( 4542): Alarm: scheduleAlarm _id = 2,
type = PRE_ALARM
01-29 22:52:00.147 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:00.194 D/GentleAlarm( 4542): Alarm: scheduleAlarm setting
alarm to 2010.01.30 n. Chr. at 22:52:00
01-29 22:52:00.202 D/GentleAlarm( 4542): Alarm: storeScheduledAlarm =>
id=2, type=MAIN_ALARM, time=2010.01.30 n. Chr. at 22:52:00,
name=Weekend, playAsTest=false, played=false
01-29 22:52:00.452 D/GentleAlarm( 4542): UtilDateFomat: is24=yes,
hasWeekdate=no
01-29 22:52:00.702 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:00.702 D/GentleAlarm( 4542): WakeLock: getInstance
01-29 22:52:00.702 D/GentleAlarm( 4542): WakeLock: disableKeyguard
01-29 22:52:00.710 D/GentleAlarm( 4542): WakeLock: acquireWakeLock
01-29 22:52:00.741 D/GentleAlarm( 4542): Alarm: storeScheduledAlarm =>
timeBegin=2010.01.29 n. Chr. at 22:52:00
01-29 22:52:00.749 D/GentleAlarm( 4542): Alarm: storeScheduledAlarm =>
cntSnoozes=0
01-29 22:52:00.757 I/ActivityManager( 1159): Starting activity: Intent
{ flg=0x10840000
cmp=com.mobitobi.android.gentlealarmtrial/.Activity_AlarmAlert (has
extras) }
01-29 22:52:00.757 W/UsageStats( 1159): Failed to persist new stats
01-29 22:52:00.796 D/GentleAlarm( 4542): Activity_Nightmode: onPause
01-29 22:52:00.803 D/GentleAlarm( 4542): Activity_AlarmAlert: onCreate
01-29 22:52:00.803 D/GentleAlarm( 4542): Media: getInstance
01-29 22:52:00.819 D/GentleAlarm( 4542): UtilDateFomat: is24=yes,
hasWeekdate=no
01-29 22:52:00.819 D/GentleAlarm( 4542): Alarm: constructor
01-29 22:52:00.819 D/GentleAlarm( 4542): Alarm: reset
01-29 22:52:00.913 D/GentleAlarm( 4542): Activity_AlarmAlert:
startAlert begin
01-29 22:52:00.921 D/GentleAlarm( 4542): Alarm: loadIntentAsCurrent
=> id=2, type=MAIN_ALARM, time=2010.01.29 n. Chr. at 22:52:00,
name=Weekend, playAsTest=false, played=false
01-29 22:52:00.921 D/GentleAlarm( 4542): Alarm: loadAlarmDetails
01-29 22:52:00.921 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:00.928 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:00.991 D/GentleAlarm( 4542): Activity_AlarmAlert:
startAlert end
01-29 22:52:00.999 D/GentleAlarm( 4542): Activity_AlarmAlert: onCreate
ended
01-29 22:52:00.999 D/GentleAlarm( 4542): Activity_AlarmAlert: onResume
01-29 22:52:01.022 D/GentleAlarm( 4542): Service_Alarm: onCreate
01-29 22:52:01.022 D/GentleAlarm( 4542): Media: getInstance
01-29 22:52:01.053 D/GentleAlarm( 4542): Service_Alarm: onStart
PLAY_ALARM
01-29 22:52:01.053 D/GentleAlarm( 4542): Alarm: constructor
01-29 22:52:01.053 D/GentleAlarm( 4542): Alarm: reset
01-29 22:52:01.053 D/GentleAlarm( 4542): Alarm: loadIntentAsCurrent
=> id=2, type=MAIN_ALARM, time=2010.01.29 n. Chr. at 22:52:00,
name=Weekend, playAsTest=false, played=false
01-29 22:52:01.053 D/GentleAlarm( 4542): Alarm: loadAlarmDetails
01-29 22:52:01.053 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:01.069 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:01.069 D/GentleAlarm( 4542): Service_Alarm: helper thread
begin
01-29 22:52:01.069 E/GentleAlarm( 4542): Media: getStreamVolume 15
01-29 22:52:01.069 D/GentleAlarm( 4542): Media: release
01-29 22:52:01.077 D/GentleAlarm( 4542): Alarm: scheduleNextAlarm
01-29 22:52:01.077 D/GentleAlarm( 4542): Alarm:
isSnoozeOrSafeAlarmScheduled no
01-29 22:52:01.077 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:01.085 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:01.085 D/GentleAlarm( 4542): Alarm: scheduleAlarm _id = 2,
type = PRE_ALARM
01-29 22:52:01.085 D/GentleAlarm( 4542): DbAdapter: create
01-29 22:52:01.108 D/GentleAlarm( 4542): Alarm: scheduleAlarm setting
alarm to 2010.01.30 n. Chr. at 22:52:00
01-29 22:52:01.108 D/GentleAlarm( 4542): Alarm: storeScheduledAlarm =>
id=2, type=MAIN_ALARM, time=2010.01.30 n. Chr. at 22:52:00,
name=Weekend, playAsTest=false, played=false
01-29 22:52:01.124 D/GentleAlarm( 4542): UtilDateFomat: is24=yes,
hasWeekdate=no
01-29 22:52:01.241 D/GentleAlarm( 4542): DbAdapter: close
01-29 22:52:01.241 D/GentleAlarm( 4542): Alarm: playAlarm _id = 2,
alarmtype = MAIN_ALARM
01-29 22:52:01.241 D/GentleAlarm( 4542): Media: play sound.id = -1,
soundtype = RINGTONE, uri =
01-29 22:52:01.241 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=1,
fade=120, delay=3870
01-29 22:52:01.241 D/GentleAlarm( 4542): Media: prepareSound sound.id
= -1
01-29 22:52:01.249 V/MediaProvider( 1317): enter query, uri:
content://media/internal/audio/media/9
01-29 22:52:01.296 D/GentleAlarm( 4542): Media: runFadeInTask sound.id
= -1, type = RINGTONE
01-29 22:52:01.296 D/GentleAlarm( 4542): Media: setStreamVolume 15
01-29 22:52:01.296 D/GentleAlarm( 4542): Media: runDurationTask
sound.id = -1, type = RINGTONE, duration = 600
01-29 22:52:01.296 D/GentleAlarm( 4542): Alarm: markAlarmAsPlayed
01-29 22:52:01.303 D/GentleAlarm( 4542): Service_Alarm: helper thread
end
01-29 22:52:01.303 D/GentleAlarm( 4542): Service_Alarm: startService
01-29 22:52:01.499 D/dalvikvm( 1159): GC freed 19038 objects / 899224
bytes in 161ms
01-29 22:52:01.624 D/GentleAlarm( 4542): Media: runFadeInTask RUNNABLE
currentStep 1, delay 3870
01-29 22:52:01.624 D/GentleAlarm( 4542): Media: setVolume
01-29 22:52:01.624 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=1,
fade=120, delay=3870
01-29 22:52:01.624 D/GentleAlarm( 4542): Media: setVolume vol=2,
playerVol=0.002765043
01-29 22:52:01.624 D/GentleAlarm( 4542): Media: start playing
01-29 22:52:01.624 D/GentleAlarm( 4542): Service_Alarm:
onCallStateChanged state=0
01-29 22:52:01.678 D/AudioHardwareMot( 1056): AudioMgr:Output 0xb4c8
exiting standby
01-29 22:52:01.811 D/dalvikvm( 4542): GC freed 21962 objects / 1425896
bytes in 101ms
01-29 22:52:02.139 I/ActivityManager( 1159): Displayed activity
com.mobitobi.android.gentlealarmtrial/.Activity_AlarmAlert: 1345 ms
(total 1345 ms)
01-29 22:52:02.139 W/UsageStats( 1159): Failed to persist new stats
01-29 22:52:05.538 D/GentleAlarm( 4542): Media: runFadeInTask RUNNABLE
currentStep 1, delay 3870
01-29 22:52:05.538 D/GentleAlarm( 4542): Media: stepVolume delta = 1
01-29 22:52:05.538 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=1,
fade=120, delay=3870
01-29 22:52:05.538 D/GentleAlarm( 4542): Media: setVolume
01-29 22:52:05.538 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=2,
fade=120, delay=3870
01-29 22:52:05.538 D/GentleAlarm( 4542): Media: setVolume vol=5,
playerVol=0.0031846901
01-29 22:52:06.108 D/TmWidgetProvider( 1312): updateAppWidget
appWidgetId=104
01-29 22:52:07.303 D/TmWidgetProvider( 1312): updateAppWidget
appWidgetId=104
01-29 22:52:09.428 D/GentleAlarm( 4542): Media: runFadeInTask RUNNABLE
currentStep 2, delay 3870
01-29 22:52:09.428 D/GentleAlarm( 4542): Media: stepVolume delta = 1
01-29 22:52:09.428 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=2,
fade=120, delay=3870
01-29 22:52:09.428 D/GentleAlarm( 4542): Media: setVolume
01-29 22:52:09.428 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=3,
fade=120, delay=3870
01-29 22:52:09.428 D/GentleAlarm( 4542): Media: setVolume vol=7,
playerVol=0.0036680268
01-29 22:52:10.757 W/ActivityManager( 1159): Launch timeout has
expired, giving up wake lock!
01-29 22:52:10.796 W/ActivityManager( 1159): Activity idle timeout for
HistoryRecord{44dc3b50
com.mobitobi.android.gentlealarmtrial/.Activity_AlarmAlert}
01-29 22:52:13.319 D/GentleAlarm( 4542): Media: runFadeInTask RUNNABLE
currentStep 3, delay 3870
01-29 22:52:13.319 D/GentleAlarm( 4542): Media: stepVolume delta = 1
01-29 22:52:13.319 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=3,
fade=120, delay=3870
01-29 22:52:13.319 D/GentleAlarm( 4542): Media: setVolume
01-29 22:52:13.319 D/GentleAlarm( 4542): Media: FadeDetail
type=RINGTONE, target=80, current=0, targetStep=32, currentSte=4,
fade=120, delay=3870
01-29 22:52:13.319 D/GentleAlarm( 4542): Media: setVolume vol=10,
playerVol=0.004224719
01-29 22:52:14.897 W/ActivityManager( 1159): Timeout of broadcast
BroadcastRecord{4503e1f0 android.intent.action.TIME_TICK} -
receiver=android.os.binderpr...@44dbc108
01-29 22:52:14.897 W/ActivityManager( 1159): Receiver during timeout:
BroadcastFilter{44e75868 ReceiverList{44e757e8 4542
com.mobitobi.android.gentlealarmtrial/10053 remote:44dbc108}}
01-29 22:52:14.928 I/ActivityManager( 1159): ANR in process:
com.mobitobi.android.gentlealarmtrial
01-29 22:52:14.928 I/ActivityManager( 1159): Annotation: Broadcast of
Intent { act=android.intent.action.TIME_TICK flg=0x40000004 (has
extras) }
01-29 22:52:14.928 I/ActivityManager( 1159): CPU usage:
01-29 22:52:14.928 I/ActivityManager( 1159): Load: 0.93 / 1.9 / 5.66
01-29 22:52:14.928 I/ActivityManager( 1159): CPU usage from 14920ms to
25ms ago:
01-29 22:52:14.928 I/ActivityManager( 1159):
com.mobitobi.android.gentlealarmtrial: 72% = 66% user + 5% kernel /
faults: 1550 minor 7 major
01-29 22:52:14.928 I/ActivityManager( 1159): system_server: 18% =
11% user + 6% kernel / faults: 2075 minor 2 major
01-29 22:52:14.928 I/ActivityManager( 1159): mediaserver: 6% = 5%
user + 0% kernel / faults: 97 minor 3 major
01-29 22:52:14.928 I/ActivityManager( 1159): com.android.settings:
0% = 0% user + 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159): pvr_workqueue: 0% = 0%
user + 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159):
com.estrongs.android.pop: 0% = 0% user + 0% kernel / faults: 34 minor
01-29 22:52:14.928 I/ActivityManager( 1159): dsi: 0% = 0% user + 0%
kernel
01-29 22:52:14.928 I/ActivityManager( 1159): pvrflip/0: 0% = 0% user
+ 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159): org.satok.gweather: 0%
= 0% user + 0% kernel / faults: 8 minor
01-29 22:52:14.928 I/ActivityManager( 1159): com.google.android.gm:
0% = 0% user + 0% kernel / faults: 42 minor
01-29 22:52:14.928 I/ActivityManager( 1159): android.process.media:
0% = 0% user + 0% kernel / faults: 11 minor
01-29 22:52:14.928 I/ActivityManager( 1159): tiwlan_wq: 0% = 0% user
+ 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159): gkisystem: 0% = 0% user
+ 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159): android.process.acore:
0% = 0% user + 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159): wpa_supplicant: 0% = 0%
user + 0% kernel
01-29 22:52:14.928 I/ActivityManager( 1159): TOTAL: 99% = 85% user +
13% kernel + 1% irq
01-29 22:52:14.928 I/ActivityManager( 1159): Removing old ANR trace
file from /data/anr/traces.txt
01-29 22:52:14.944 I/Process ( 1159): Sending signal. PID: 4542 SIG: 3
01-29 22:52:14.944 I/dalvikvm( 4542): threadid=7: reacting to signal 3
01-29 22:52:14.944 I/dalvikvm( 4542): Wrote stack trace to '/data/anr/
traces.txt'
--
You received this message because you are subscribed to the Google
Groups "Android Developers" group.
To post to this group, send email to [email protected]
To unsubscribe from this group, send email to
[email protected]
For more options, visit this group at
http://groups.google.com/group/android-developers?hl=en
