Android engine silently crashing - May be multithreaded audio?

monkey0506 · Wed 23/10/2013 05:19:39

I don't know what I'm doing wrong, but I can't seem to reproduce this for the life of me.

Unfortunately, it seems everyone else is running into this issue:

QuoteOne more issue I have noticed with the Android port is that it tends to exit sometimes after the game has been running for 5 - 10 minutes. No error messages are given, it just exits cleanly. It's also possible for it to get stuck (e.g. screen frozen/music glitching repeatedly) after the same length of time. I'm not sure why this is.

QuoteI've been having some beta testers play through our game on Android using the latest AGS build from JJS's daily page. All of the testers have experienced these dropouts often, even the ones running the game on faster devices with Jellybean.

Logcat output from crash:

Spoiler

QuoteHP Touchpad running Cyanogen 9, android 4.0.4 (9" tablet)
Random crash of AGS application when quickly clicking on several icons. It's a clean exit

F/libc ( 8520): Fatal signal 11 (SIGSEGV) at 0x00004548 (code=1)
I/DEBUG (30199): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
I/DEBUG (30199): Build fingerprint: 'hp/hp_tenderloin/tenderloin:4.0.4/IMM76I/330937:user/release-keys'
I/DEBUG (30199): pid: 8520, tid: 8588 >>> com.bigbluecup.android.launcher <<<
I/DEBUG (30199): signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 00004548
I/DEBUG (30199): r0 00400000 r1 0022a400 r2 000022a4 r3 00000000
I/DEBUG (30199): r4 477d63ac r5 0027c2e0 r6 0000015c r7 00400000
I/DEBUG (30199): r8 477e7390 r9 00000000 10 00000100 fp 00000000
I/DEBUG (30199): ip 00004548 sp 46e7ee48 lr 47588728 pc 4758862c cpsr 200f0010
I/DEBUG (30199): d0 0000000000000000 d1 0000000000000000
I/DEBUG (30199): d2 0000000000000000 d3 0000000000000000
I/DEBUG (30199): d4 002b005300200032 d5 000a00650027006a
I/DEBUG (30199): d6 ffeb0061fff60063 d7 ffd2004affda0053
I/DEBUG (30199): d8 0000000000000000 d9 0000000000000000
I/DEBUG (30199): d10 0000000000000000 d11 0000000000000000
I/DEBUG (30199): d12 0000000000000000 d13 0000000000000000
I/DEBUG (30199): d14 0000000000000000 d15 0000000000000000
I/DEBUG (30199): d16 0000000700001000 d17 ff92fffeffa00011
I/DEBUG (30199): d18 ff7bffd9ff85ffeb d19 ff63ffb9ff6effc6
I/DEBUG (30199): d20 ff56ffacff5fffb4 d21 ff3bff94ff44ff9d
I/DEBUG (30199): d22 ff52ff9fff47ff9a d23 ff69ffadff58ffa0
I/DEBUG (30199): d24 0000000000000000 d25 0000f8f200009df5
I/DEBUG (30199): d26 0002b4c5001220a4 d27 0001f8f300029df7
I/DEBUG (30199): d28 0000000000000000 d29 090a0b0c0d0e0f10
I/DEBUG (30199): d30 0000000900000009 d31 0000000900000009
I/DEBUG (30199): scr 60000012
I/DEBUG (30199):
I/DEBUG (30199): #00 pc 4758862c /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): #01 lr 47588728 /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199):
I/DEBUG (30199): code around pc:
I/DEBUG (30199): 4758860c e58d7044 e3560000 0a000045 e5941010 Dp....V.E.......
I/DEBUG (30199): 4758861c e594300c e1a02441 e1a0c082 e5940018 .0..A$..........
I/DEBUG (30199): 4758862c e193c0bc e2407c01 e1a0c40c e1510007 .....|@.......Q.
I/DEBUG (30199): 4758863c e24cc502 ba00011e e5982004 e2022005 ..L...... ... ..
I/DEBUG (30199): 4758864c e3520001 0a000466 e5947020 e20130ff ..R.f... p...0..
I/DEBUG (30199):
I/DEBUG (30199): code around lr:
I/DEBUG (30199): 47588708 e5883004 e2466001 e316000f 1affffbd .0...`F.........
I/DEBUG (30199): 47588718 e1a00004 e1a01008 e1a02006 ebfffb4f ......... ..O...
I/DEBUG (30199): 47588728 e3560000 1affffb9 e59d7044 eafffe46 ..V.....Dp..F...
I/DEBUG (30199): 47588738 e59d9044 e59d8028 e3a03000 e59d7048 D...(....0..Hp..
I/DEBUG (30199): 47588748 e7893008 eafffe40 e594201c e06c3003 .0..@.... ...0l.
I/DEBUG (30199):
I/DEBUG (30199): memory map around addr 00004548:
I/DEBUG (30199): (no map below)
I/DEBUG (30199): (no map for address)
I/DEBUG (30199): 00008000-0000a000 /system/bin/app_process
I/DEBUG (30199):
I/DEBUG (30199): stack:
I/DEBUG (30199): 46e7ee08 00000000
I/DEBUG (30199): 46e7ee0c 00000000
I/DEBUG (30199): 46e7ee10 00000000
I/DEBUG (30199): 46e7ee14 00000000
I/DEBUG (30199): 46e7ee18 2b345fa8 /system/lib/libdvm.so
I/DEBUG (30199): 46e7ee1c 00000000
I/DEBUG (30199): 46e7ee20 46e82fb0
I/DEBUG (30199): 46e7ee24 00000000
I/DEBUG (30199): 46e7ee28 00000000
I/DEBUG (30199): 46e7ee2c 00000000
I/DEBUG (30199): 46e7ee30 00000000
I/DEBUG (30199): 46e7ee34 00000000
I/DEBUG (30199): 46e7ee38 477d63ac
I/DEBUG (30199): 46e7ee3c 0027c2c0 [heap]
I/DEBUG (30199): 46e7ee40 df0027ad
I/DEBUG (30199): 46e7ee44 00000000
I/DEBUG (30199): 46e7ee48 416cbdb0 /dev/ashmem/dalvik-LinearAlloc (deleted)
I/DEBUG (30199): 46e7ee4c 46e7eebc
I/DEBUG (30199): 46e7ee50 073e6000
I/DEBUG (30199): 46e7ee54 00000000
I/DEBUG (30199): 46e7ee58 072fe000
I/DEBUG (30199): 46e7ee5c 00000000
I/DEBUG (30199): 46e7ee60 00000000
I/DEBUG (30199): 46e7ee64 00000000
I/DEBUG (30199): 46e7ee68 00000000
I/DEBUG (30199): 46e7ee6c 00000000
I/DEBUG (30199): 46e7ee70 00000100
I/DEBUG (30199): 46e7ee74 073e44d6
I/DEBUG (30199): 46e7ee78 477ebc64
I/DEBUG (30199): 46e7ee7c 47700d7c /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): 46e7ee80 477d636c
I/DEBUG (30199): 46e7ee84 0024e55c [heap]
I/DEBUG (30199): 46e7ee88 0024e308 [heap]
I/DEBUG (30199): 46e7ee8c 00000001
I/DEBUG (30199): 46e7ee90 00000000
I/DEBUG (30199): 46e7ee94 0027adc0 [heap]
I/DEBUG (30199): 46e7ee98 477d636c
I/DEBUG (30199): 46e7ee9c 477d636c
I/DEBUG (30199): 46e7eea0 477d6e84
I/DEBUG (30199): 46e7eea4 477d6380
I/DEBUG (30199): 46e7eea8 477e0c00
I/DEBUG (30199): 46e7eeac ffffffff
I/DEBUG (30199): 46e7eeb0 47700d7c /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): 46e7eeb4 477e2c00
I/DEBUG (30199): 46e7eeb8 477e0c00
I/DEBUG (30199): 46e7eebc 47700d7c /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): 46e7eec0 fffffe48
I/DEBUG (30199): 46e7eec4 477e0c00
I/DEBUG (30199): 46e7eec8 475a9be4 /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): 46e7eecc 00100000 [heap]
I/DEBUG (30199): 46e7eed0 00000000
I/DEBUG (30199): 46e7eed4 475a9c30 /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): 46e7eed8 46e7ef00
I/DEBUG (30199): 46e7eedc 475a9be4 /data/data/com.bigbluecup.android.launcher/lib/libagsengine.so
I/DEBUG (30199): 46e7eee0 00000000
I/DEBUG (30199): 46e7eee4 00000078
I/DEBUG (30199): 46e7eee8 46d7f000
I/DEBUG (30199): 46e7eeec 2aac21d0 /system/lib/libc.so
I/DEBUG (30199): 46e7eef0 46e7ef00
I/DEBUG (30199): 46e7eef4 0028d978 [heap]
I/DEBUG (30199): 46e7eef8 2aae9318 /system/lib/libc.so
I/DEBUG (30199): 46e7eefc 2aac1d00 /system/lib/libc.so
I/DEBUG (30199): 46e7ef00 46e7ef00
I/DEBUG (30199): 46e7ef04 0028d978 [heap]
I/DEBUG (30199): 46e7ef08 00000000
I/DEBUG (30199): 46e7ef0c 00000000
I/DEBUG (30199): 46e7ef10 00000000
I/DEBUG (30199): 46e7ef14 00000000
I/DEBUG (30199): 46e7ef18 0027dd70 [heap]
I/DEBUG (30199): 46e7ef1c 00000000
I/DEBUG (30199): 46e7ef20 00000000
I/DEBUG (30199): 46e7ef24 00000000
I/DEBUG (30199): 46e7ef28 00000000
I/DEBUG (30199): 46e7ef2c 00000000
I/DEBUG (30199): 46e7ef30 00000000
I/DEBUG (30199): 46e7ef34 00000000
I/DEBUG (30199): 46e7ef38 00000000
I/DEBUG (30199): 46e7ef3c 00000000
I/DEBUG (30199): 46e7ef40 00000000
I/DEBUG (30199): 46e7ef44 00000000
I/DEBUG (30199): 46e7ef48 00000000
I/DEBUG (30199): 46e7ef4c 00000000
W/AudioTrack( 8520): obtainBuffer() track 0x28d488 disabled, restarting
W/AudioTrack( 8520): obtainBuffer() track 0x28d488 disabled, restarting
I/BootReceiver( 240): Copying /data/tombstones/tombstone_01 to DropBox (SYSTEM_TOMBSTONE)
I/ActivityManager( 240): Process com.bigbluecup.android.launcher (pid 8520) has died.
W/ActivityManager( 240): Force removing ActivityRecord{2bb34700 com.bigbluecup.android.launcher/com.bigbluecup.android.AgsEngine}: app died, no saved state
I/WindowManager( 240): WIN DEATH: Window{2bd0b4d8 com.bigbluecup.android.launcher/com.bigbluecup.android.AgsEngine paused=false}
W/WindowManager( 240): Force-removing child win Window{2bde9420 SurfaceView paused=false} from container Window{2bd0b4d8 com.bigbluecup.android.launcher/com.bigbluecup.android.AgsEngine paused=false}
D/Zygote ( 158): Process 8520 terminated by signal (11)
D/dalvikvm( 240): GC_CONCURRENT freed 3276K, 42% free 14540K/24839K, paused 6ms+12ms
W/WindowManager( 240): Failed looking up window
W/WindowManager( 240): java.lang.IllegalArgumentException: Requested window android.os.BinderProxy@2bd51378 does not exist
W/WindowManager( 240): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:7185)
W/WindowManager( 240): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:7176)
W/WindowManager( 240): at com.android.server.wm.WindowState$DeathRecipient.binderDied(WindowState.java:1545)
W/WindowManager( 240): at android.os.BinderProxy.sendDeathNotice(Binder.java:417)
W/WindowManager( 240): at dalvik.system.NativeStart.run(Native Method)
I/WindowManager( 240): WIN DEATH: null
W/InputManagerService( 240): Got RemoteException sending setActive(false) notification to pid 8520 uid 10155
I/ALSAModule(23747): android::status_t android::s_close(android::alsa_handle_t*): SENDING out disable sequence
I/ALSAModule(23747): ALSA Module: closing down output device

[close]

These lines in particular from that logcat is definitely reinforcing my concerns that it may relate to the multithreaded audio:

QuoteW/AudioTrack( 8520): obtainBuffer() track 0x28d488 disabled, restarting
W/AudioTrack( 8520): obtainBuffer() track 0x28d488 disabled, restarting
I/ActivityManager( 240): Process com.bigbluecup.android.launcher (pid 8520) has died.

Another Logcat: (less complete info)

Spoiler

QuoteI/SurfaceFlinger(29688): id=1836 Removed com.bigbluecup.android.launcher/com.bigbluecup.android.AgsEngine idx=-2 Map Size=2
W/WindowManager(29721): Failed looking up window
W/WindowManager(29721): java.lang.IllegalArgumentException: Requested window android.os.BinderProxy@40f848e8 does not exist
W/WindowManager(29721): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:7174)
W/WindowManager(29721): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:7165)
W/WindowManager(29721): at com.android.server.wm.WindowState$DeathRecipient.binderDied(WindowState.java:1412)
W/WindowManager(29721): at android.os.BinderProxy.sendDeathNotice(Binder.java:418)
W/WindowManager(29721): at com.android.server.SystemServer.init1(Native Method)
W/WindowManager(29721): at com.android.server.SystemServer.main(SystemServer.java:831)
W/WindowManager(29721): at java.lang.reflect.Method.invokeNative(Native Method)
W/WindowManager(29721): at java.lang.reflect.Method.invoke(Method.java:491)
W/WindowManager(29721): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:849)
W/WindowManager(29721): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:607)
W/WindowManager(29721): at dalvik.system.NativeStart.main(Native Method)
I/WindowManager(29721): WIN DEATH: null
I/WindowManager(29721): WINDOW DIED Window{40ee86d8 com.bigbluecup.android.launcher/com.bigbluecup.android.AgsEngine paused=false}
I/ActivityManager(29721): Start proc com.android.launcher for activity com.android.launcher/com.android.launcher2.Launcher: pid=24063 uid=10072 gids={}
V/WindowManager(29721): rotationForOrientationLw(orient=-1, last=0); user=0 displayEnabled=true mHdmiPlugged=false mLidOpen=-1 mDockMode=0 (useSensorForOrientationLp(orientation)=true mAccelerometerDefault=1
V/WindowManager(29721): new rotation is set to 0
D/KeyguardViewMediator(29721): setHidden false
I/ActivityThread(24063): Pub com.android.launcher2.settings: com.android.launcher2.LauncherProvider
D/StatusBar.NetworkController(29784): refreshViews combinedSignalIconId=0x7f020142/(null) dataDirectionOverlayIconId=0x0 mAirplaneMode=false mDataActivity=0 mPhoneSignalIconId=0x7f020130 mDataDirectionIconId=0x0 mDataSignalIconId=0x7f020114 mDataTypeIconId=0x0 mWifiIconId=0x7f020142 mBluetoothTetherIconId=0x1080530
D/StatusBar.NetworkController(29784): changing data overlay icon id to 0

[close]

Quote...the game screen froze (like it usually does when it's about to drop out). But this time, it froze with the player's talking dialog portrait came on-screen, before he could say his speech line. At this point while his dialog portrait was 'frozen', I could still move the mouse around the screen to see the names of hotspots change on the lower tooltip GUI. This indicated that the entire game wasn't frozen, but it seemed to be just waiting on the speech audio to buffer or otherwise do something before it would play. The speech audio never ended up actually playing. The game dropped out about 5 seconds later, while the dialog portrait was still on the screen waiting for the speech line to start (and while I was still seeing hotspot names appear on the tooltip GUI as I moved the mouse around). Not sure how helpful that is, but hopefully it sheds some more light on what the crashing issue could be related to.

As an aside, I should also mention that these types of freezes/dropouts are far less frequent on my Galaxy S1/Gingerbread. After playing the game for 8 hours or so, I only experienced about 3 such crashes. while on my S3/Jellybean, they tend to occur in intervals of 2 to 15 minutes on a regular basis.

From my stand-alone APK beta:

QuoteEverything seemed to be working well. No slowdown. Right up until the point where I tapped the "menu" hard button and then tapped on "Instructions". As I was scrolling through the instructions, the game exited cleanly without any error message (a bug I have experienced frequently with other AGS games in the JJS Android port).

Repeating the same actions a second time didn't cause the game to exit, so this supports my theory that it seems to be arbitrary and can happen at any time, on fast and slow Android devices alike.

That's about the sum of the info I've collected. I'm highly suspicious of the multithreaded audio (especially after a summary review of the longer logcat), but I can't make enough sense of it to know what I'm looking for, and I can't reproduce it on my HTC Evo 3D (Android 4.0.3, IIRC).

If anyone can make any sense of this, I would be immensely grateful (as would the players, I can assure you!). $:-\$

Crimson Wizard · Wed 23/10/2013 07:37:41

I am afraid I won't be much help here, but two questions that naturally come to mind:
1) have you tried running the games on Windows with the recent engine?
2) have you tried disabling threaded audio to see the difference? I belive it should be "[sound]"-"threaded" option in "android.cfg".

There's also a newer sound cache system, although AFAIK it should not be used for voice files. It is controlled by "[sound]"-"cache_size" parameter.

BTW, unlike music and sounds, that are loaded fully into memory, voice files are streamed: read part by part from the data file (in callback). Maybe that is related somehow. Is it possible to test game(s) with different types of sound off, like all sounds off (in config), only music on, only voice on?

I recall only one crash related to audio, that happened when the game was actually aborted intentionally by the engine due error in script, while music was playing in background.

monkey0506 · Thu 24/10/2013 10:02:45

Thanks for the tips, I'll try to look more into those areas.

One thing on the coding side I'm actually looking into is that the threading implementation used is completely exception unsafe. I'm not certain that the areas where the locking occurs is definitely throwing any exceptions (still looking more into that), but if it did then it would basically leak the lock and freeze the thread indefinitely. C++11 has some threading classes built into the STL, so I can basically emulate the std::lock_guard<> class template for the BaseMutex class. That should be sufficient to at least guarantee that this isn't an issue (and it's an incredibly simple class).

Crimson Wizard · Thu 24/10/2013 10:11:17

Yes, indeed, simple wrapper that locks mutex object in constructor, and unlocks in destructor, this will be useful. I had similar thoughts when I saw that some mutex-protected functions exit prematurely on error.

monkey0506 · Thu 24/10/2013 10:43:37

In actually implementing the lock guard it occurs to me that it could be useful to have a Release method for that class to allow releasing the lock before the object itself goes out of scope. The destructor would still release the lock if held, but there are cases where there's code such as:

Code: cpp

_mutex.Lock()
// some code
_mutex.Unlock()
// ...
_mutex.Lock()
// some more code
_mutex.Unlock()

Within the same function, locking and releasing the mutex multiple times separately from each other. As C++ doesn't have a "lock" statement like C# does, this could get quite ugly I think without implementing an Acquire/Release mechanic.

Crimson Wizard · Fri 25/10/2013 12:09:19

While you are at this, I would suggest reimplementing UPDATE_MP3 and UPDATE_MP3_THREAD macros as functions (not sure there's a necessity of explicitly making them inline).

(Well, I can do that myself if you do not want to touch these parts)

monkey0506 · Sun 27/10/2013 21:50:27

I'm still waiting on getting some results back from others who have experienced the crash, but I tested this on another Android device and signs seem to indicate that the mutex lock I implemented (in my fork) may have improved the situation. The other device is an HTC Thunderbolt, and while it runs the game significantly slower, there's also been no crashes on that device. Reports of the crashes have indicated crashing in/around areas where speech files are being used, and the Thunderbolt actually has been hanging up (freezing momentarily) around these areas, but without actually crashing!

Unfortunately my laptop's HDD crashed yesterday, so I'm in the process of reacquiring the various tools and resources necessary to recreate my projects (stupidly, I didn't have any recent backups of the project folders

). All-in-all it's not a major loss (code-wise), but it will be a little while still before I can really be entirely sure.

I appreciate your help and suggestions CW. You're a great asset.

Android engine silently crashing - May be multithreaded audio?

monkey0506

Crimson Wizard

monkey0506

Crimson Wizard

monkey0506

Crimson Wizard

monkey0506