Closed Bug 1057073 Opened 11 years ago Closed 8 years ago

Intermittent Android test_dataChannel_basicAudioVideo.html | application timed out after 330 seconds with no output

Categories

(Core :: WebRTC, defect, P4)

ARM
Android
defect

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: RyanVM, Assigned: padenot)

References

Details

(Keywords: crash, intermittent-failure)

Attachments

(1 file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=46482185&tree=Mozilla-Inbound Android 4.0 Panda mozilla-inbound opt test mochitest-6 on 2014-08-21 09:54:13 PDT for push 36ffb9b24c56 slave: panda-0892 10:07:27 INFO - 155 INFO TEST-START | /tests/dom/media/tests/mochitest/test_dataChannel_basicAudioVideo.html 10:13:12 INFO - org.mozilla.fennec still alive after SIGABRT: waiting... 10:13:17 WARNING - TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicAudioVideo.html | application timed out after 330 seconds with no output 10:13:17 INFO - INFO | automation.py | Application ran for: 0:07:53.555314 10:13:17 INFO - INFO | zombiecheck | Reading PID log: /tmp/tmpPW94sipidlog 10:13:18 INFO - Contents of /data/anr/traces.txt: 10:13:18 INFO - ----- pid 2246 at 2014-08-21 10:13:08 ----- 10:13:18 INFO - Cmd line: org.mozilla.fennec 10:13:18 INFO - DALVIK THREADS: 10:13:18 INFO - (mutexes: tll=0 tsl=0 tscl=0 ghl=0) 10:13:18 INFO - "main" prio=5 tid=1 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x40b82460 self=0x6c6830 10:13:18 INFO - | sysTid=2246 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1074328740 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=108 stm=26 core=0 10:13:18 INFO - at android.os.MessageQueue.nativePollOnce(Native Method) 10:13:18 INFO - at android.os.MessageQueue.next(MessageQueue.java:118) 10:13:18 INFO - at android.os.Looper.loop(Looper.java:118) 10:13:18 INFO - at android.app.ActivityThread.main(ActivityThread.java:4424) 10:13:18 INFO - at java.lang.reflect.Method.invokeNative(Native Method) 10:13:18 INFO - at java.lang.reflect.Method.invoke(Method.java:511) 10:13:18 INFO - at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784) 10:13:18 INFO - at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551) 10:13:18 INFO - at dalvik.system.NativeStart.main(Native Method) 10:13:18 INFO - "pool-1-thread-1" prio=5 tid=19 WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x412f1a38 self=0xb28cb8 10:13:18 INFO - | sysTid=2326 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=11695448 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=0 10:13:18 INFO - at java.lang.Object.wait(Native Method) 10:13:18 INFO - - waiting on <0x41347568> (a java.lang.VMThread) held by tid=19 (pool-1-thread-1) 10:13:18 INFO - at java.lang.Thread.parkFor(Thread.java:1231) 10:13:18 INFO - at sun.misc.Unsafe.park(Unsafe.java:323) 10:13:18 INFO - at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157) 10:13:18 INFO - at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022) 10:13:18 INFO - at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413) 10:13:18 INFO - at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009) 10:13:18 INFO - at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069) 10:13:18 INFO - at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@41309a80" daemon prio=5 tid=18 WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x4136a870 self=0xa8f7e0 10:13:18 INFO - | sysTid=2325 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=10897168 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=0 10:13:18 INFO - at java.lang.Object.wait(Native Method) 10:13:18 INFO - - waiting on <0x413b1fc0> (a java.lang.ref.ReferenceQueue) 10:13:18 INFO - at java.lang.Object.wait(Object.java:401) 10:13:18 INFO - at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102) 10:13:18 INFO - at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73) 10:13:18 INFO - at org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:102) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "Thread-98" prio=5 tid=16 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x413c9cc0 self=0xa68d48 10:13:18 INFO - | sysTid=2294 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=10914240 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=2400 stm=528 core=1 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - "actionMode" prio=5 tid=15 WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x413a6738 self=0x9d8250 10:13:18 INFO - | sysTid=2268 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=10318720 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at java.lang.Object.wait(Native Method) 10:13:18 INFO - - waiting on <0x413a6738> (a java.util.Timer$TimerImpl) 10:13:18 INFO - at java.lang.Object.wait(Object.java:364) 10:13:18 INFO - at java.util.Timer$TimerImpl.run(Timer.java:214) 10:13:18 INFO - "Gecko" prio=5 tid=14 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x413a3a00 self=0x9d29c8 10:13:18 INFO - | sysTid=2267 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=10313080 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=4475 stm=338 core=0 10:13:18 INFO - at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method) 10:13:18 INFO - at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:363) 10:13:18 INFO - at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:186) 10:13:18 INFO - "pool-2-thread-1" prio=5 tid=13 WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x4130ea10 self=0x8919e8 10:13:18 INFO - | sysTid=2265 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8720304 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at java.lang.Object.wait(Native Method) 10:13:18 INFO - - waiting on <0x4130eb58> (a java.lang.VMThread) held by tid=13 (pool-2-thread-1) 10:13:18 INFO - at java.lang.Thread.parkFor(Thread.java:1231) 10:13:18 INFO - at sun.misc.Unsafe.park(Unsafe.java:323) 10:13:18 INFO - at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157) 10:13:18 INFO - at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022) 10:13:18 INFO - at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413) 10:13:18 INFO - at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009) 10:13:18 INFO - at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069) 10:13:18 INFO - at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "GeckoANRReporter" daemon prio=5 tid=12 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x4126ab60 self=0x8633b8 10:13:18 INFO - | sysTid=2260 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8514640 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=0 10:13:18 INFO - at android.os.MessageQueue.nativePollOnce(Native Method) 10:13:18 INFO - at android.os.MessageQueue.next(MessageQueue.java:118) 10:13:18 INFO - at android.os.Looper.loop(Looper.java:118) 10:13:18 INFO - at org.mozilla.gecko.ANRReporter$1.run(ANRReporter.java:95) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "GeckoBackgroundThread" prio=5 tid=11 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x412907b8 self=0x89a578 10:13:18 INFO - | sysTid=2259 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8494816 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=33 stm=6 core=0 10:13:18 INFO - at android.os.MessageQueue.nativePollOnce(Native Method) 10:13:18 INFO - at android.os.MessageQueue.next(MessageQueue.java:118) 10:13:18 INFO - at android.os.Looper.loop(Looper.java:118) 10:13:18 INFO - at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:32) 10:13:18 INFO - "Binder Thread #2" prio=5 tid=10 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x411dd980 self=0x88d850 10:13:18 INFO - | sysTid=2257 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8298608 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=0 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - "Binder Thread #1" prio=5 tid=9 NATIVE 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x411dd828 self=0x895820 10:13:18 INFO - | sysTid=2256 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8602880 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - "FinalizerWatchdogDaemon" daemon prio=5 tid=8 TIMED_WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x411d9ed8 self=0x7e6110 10:13:18 INFO - | sysTid=2255 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8605312 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at java.lang.VMThread.sleep(Native Method) 10:13:18 INFO - at java.lang.Thread.sleep(Thread.java:1031) 10:13:18 INFO - at java.lang.Thread.sleep(Thread.java:1013) 10:13:18 INFO - at java.lang.Daemons$FinalizerWatchdogDaemon.run(Daemons.java:213) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "FinalizerDaemon" daemon prio=5 tid=7 WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x411d9d80 self=0x885080 10:13:18 INFO - | sysTid=2254 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8607280 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at java.lang.Object.wait(Native Method) 10:13:18 INFO - - waiting on <0x40b785d0> (a java.lang.ref.ReferenceQueue) 10:13:18 INFO - at java.lang.Object.wait(Object.java:401) 10:13:18 INFO - at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102) 10:13:18 INFO - at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73) 10:13:18 INFO - at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:168) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "ReferenceQueueDaemon" daemon prio=5 tid=6 WAIT 10:13:18 INFO - | group="main" sCount=1 dsCount=0 obj=0x411d9c18 self=0x89e898 10:13:18 INFO - | sysTid=2253 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8330752 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at java.lang.Object.wait(Native Method) 10:13:18 INFO - - waiting on <0x40b784f8> 10:13:18 INFO - at java.lang.Object.wait(Object.java:364) 10:13:18 INFO - at java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:128) 10:13:18 INFO - at java.lang.Thread.run(Thread.java:856) 10:13:18 INFO - "Compiler" daemon prio=5 tid=5 VMWAIT 10:13:18 INFO - | group="system" sCount=1 dsCount=0 obj=0x411d9b28 self=0x88aca0 10:13:18 INFO - | sysTid=2252 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8597392 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=27 stm=13 core=1 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - "JDWP" daemon prio=5 tid=4 VMWAIT 10:13:18 INFO - | group="system" sCount=1 dsCount=0 obj=0x411d9a40 self=0x86b478 10:13:18 INFO - | sysTid=2251 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8325384 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - "Signal Catcher" daemon prio=5 tid=3 RUNNABLE 10:13:18 INFO - | group="system" sCount=0 dsCount=0 obj=0x411d9948 self=0x74c260 10:13:18 INFO - | sysTid=2250 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8336976 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=1 stm=0 core=0 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - "GC" daemon prio=5 tid=2 VMWAIT 10:13:18 INFO - | group="system" sCount=1 dsCount=0 obj=0x411d9868 self=0x848da8 10:13:18 INFO - | sysTid=2249 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=8420168 10:13:18 INFO - | schedstat=( 0 0 0 ) utm=28 stm=2 core=0 10:13:18 INFO - at dalvik.system.NativeStart.run(Native Method) 10:13:18 INFO - ----- end 2246 ----- 10:13:18 INFO - /data/tombstones does not exist; tombstone check skipped 10:13:19 INFO - 156 INFO mozcrash Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android/1408638016/fennec-34.0a1.en-US.android-arm.crashreporter-symbols.zip 10:13:23 INFO - 157 INFO mozcrash Saved minidump as /builds/panda-0892/test/build/blobber_upload_dir/3d108691-dfe6-c1b1-171fe4cb-4896d6ba.dmp 10:13:23 INFO - 158 INFO mozcrash Saved app info as /builds/panda-0892/test/build/blobber_upload_dir/3d108691-dfe6-c1b1-171fe4cb-4896d6ba.extra 10:13:23 WARNING - PROCESS-CRASH | /tests/dom/media/tests/mochitest/test_dataChannel_basicAudioVideo.html | application crashed [@ libc.so + 0xcff0] 10:13:23 INFO - Crash dump filename: /tmp/tmpVIvKKf/3d108691-dfe6-c1b1-171fe4cb-4896d6ba.dmp 10:13:23 INFO - Operating system: Android 10:13:23 INFO - 0.0.0 Linux 3.2.0+ #2 SMP PREEMPT Thu Nov 29 08:06:57 EST 2012 armv7l pandaboard/pandaboard/pandaboard:4.0.4/IMM76I/5:eng/test-keys 10:13:23 INFO - CPU: arm 10:13:23 INFO - 2 CPUs 10:13:23 INFO - Crash reason: SIGABRT 10:13:23 INFO - Crash address: 0x96e 10:13:23 INFO - Thread 0 (crashed) 10:13:23 INFO - 0 libc.so + 0xcff0 10:13:23 INFO - r4 = 0xffffffff r5 = 0x0083ae54 r6 = 0x00000001 r7 = 0x000000fc 10:13:23 INFO - r8 = 0x00000000 r9 = 0x00000000 r10 = 0x0083ae40 fp = 0xffffffff 10:13:23 INFO - sp = 0xbedec518 lr = 0x4012b513 pc = 0x40030ff0 10:13:23 INFO - Found by: given as instruction pointer in context 10:13:23 INFO - 1 dalvik-heap (deleted) + 0x10b6 10:13:23 INFO - sp = 0xbedec524 pc = 0x40b740b8 10:13:23 INFO - Found by: stack scanning 10:13:23 INFO - 2 libdvm.so + 0x60205 10:13:23 INFO - sp = 0xbedec528 pc = 0x40957207 10:13:23 INFO - Found by: stack scanning 10:13:23 INFO - 3 libdvm.so + 0xd9f42 10:13:23 INFO - sp = 0xbedec53c pc = 0x409d0f44 10:13:23 INFO - Found by: stack scanning 10:13:23 INFO - 4 libdvm.so + 0xba2ca 10:13:23 INFO - sp = 0xbedec540 pc = 0x409b12cc 10:13:23 INFO - Found by: stack scanning 10:13:23 INFO - 5 libdvm.so + 0xba2c2 10:13:23 INFO - sp = 0xbedec544 pc = 0x409b12c4 10:13:23 INFO - Found by: stack scanning
Every failure under the sun with a timeout is getting logged into this bug; there are 3 or 4 test_dataChannel_basicAudioVideo.html out of the 28 reports here; most of them are in entirely different modules. I think it's because the code to handle timeouts on the pandas forces a crash, and the signature of the crash gets matched to this.
Flags: needinfo?(ryanvm)
Very likely another variant of bug 1054292.
Flags: needinfo?(ryanvm)
Attached patch patch — — Splinter Review
Not sure where the `mStreamOrderDirty = false` went, but this is a pretty big win in terms of perf (last I measured, I haven't done so for sime time, now), so we should make sure it stays in the code. I don't really know for how long we've been running without it, so I pushed a try run, it might be broken, now: https://tbpl.mozilla.org/?tree=Try&rev=43726f73fe92
Attachment #8487170 - Flags: review?(karlt)
Assignee: nobody → paul
Status: NEW → ASSIGNED
Hrm, the previous try was not great, let's try this, with only this patch applied: https://tbpl.mozilla.org/?tree=Try&rev=670e1fd899af
Comment on attachment 8487170 [details] [diff] [review] patch Well, it appears that this code never got landed, and a no-op broken version of the patch landed instead. Of course, this is orange on try.
Attachment #8487170 - Flags: review?(karlt)
Depends on: 932400
Summary: Intermittent Android test_dataChannel_basicAudioVideo.html | application timed out after 330 seconds with no output | application crashed [@ libc.so + 0xcff0] → Intermittent Android test_dataChannel_basicAudioVideo.html | application timed out after 330 seconds with no output
Paul - looks like you had a patch that was orange on try and then this fell off your radar. Can you finish this in fx 42 cycle?
backlog: --- → webRTC+
Rank: 35
Flags: needinfo?(padenot)
Priority: -- → P3
This looks like an issue during shutdown. Some people are changing the way we do shutdown, and in particular the point in time when we shutdown MSG. I'd wait for a bit, things might just get better.
Flags: needinfo?(padenot)
Mass change P3->P4 to align with new Mozilla triage process.
Priority: P3 → P4
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: