The default bug view has changed. See this FAQ.

Camera not working anymore

VERIFIED FIXED in Firefox 17

Status

()

Core
Audio/Video
VERIFIED FIXED
5 years ago
5 years ago

People

(Reporter: gerard, Assigned: roc)

Tracking

unspecified
mozilla18
ARM
Gonk (Firefox OS)
Points:
---

Firefox Tracking Flags

(blocking-basecamp:+, firefox17 fixed)

Details

(Whiteboard: [qa!], [getUserMedia], [blocking-gum+])

Attachments

(3 attachments, 1 obsolete attachment)

(Reporter)

Description

5 years ago
No more preview working in Camera app, no more camera working. Since roughly 21st, August.

Logcat (when broken) :
$ adb logcat | grep -i "camera viewfinder"
I/Gecko   (  241): camera viewfinder is unknown
I/Gecko   (  241): camera viewfinder is consuming

Logcat (when working) :
$ adb logcat | grep -i "camera viewfinder"
I/Gecko   (  345): camera viewfinder is consuming
I/Gecko   (  345): camera viewfinder is not consuming

bisecting with git gives the following commit:

---
8d75feebe8cafe014d553d6f7653a13c8db737fa is the first bad commit
commit 8d75feebe8cafe014d553d6f7653a13c8db737fa
Author: Robert O'Callahan <robert@ocallahan.org>
Date:   Wed Aug 1 00:17:21 2012 +1200

    Bug 779715. Part 1: Add basic support for ProcessedMediaStreams. r=jesup
    The main thing this patch does is to add ProcessedMediaStream objects and
    MediaInputPorts connecting streams. ProcessedMediaStreams are an abstract
    class that doesn't constrain what processing is actually performed, except
    that for now we assume a stream's processing depends only on its inputs
    window of data between mCurrentTime and mStateComputedTime.
    This patch reorganizes the way the blocking status of each stream is computed.
    The streams are partitioned into groups so that every stream which can affect
    the blocking status of another stream is in the same group as that other stream.
    We also add a pass to order the streams by dependency so we can process the streams
    in order of dependency; this pass also identifies the streams that form part of a
    cycle.
    
    --HG--
    extra : rebase_source : c45c931a264e73f295642a934500bbeaa6448774

:040000 040000 9ec2cc6f184b9b2a14ca93317c14fc2775ca00b4 0cd45ea944fa09c23f9741c54bec158e9c69cfa9 M	content
(In reply to Alexandre LISSY from comment #0)
> $ adb logcat | grep -i "camera viewfinder"
> I/Gecko   (  241): camera viewfinder is unknown
> I/Gecko   (  241): camera viewfinder is consuming

That's weird. "unknown" seems wrong, since the only caller of NotifyConsumptionChanged is MediaStreamGraphImpl::UpdateConsumptionState, which passes
  MediaStreamListener::Consumption state =
      aStream->mIsConsumed ? MediaStreamListener::CONSUMED
      : MediaStreamListener::NOT_CONSUMED;
So I would love to see a stack of how we hit "unknown" there.
Created attachment 654506 [details] [diff] [review]
patch

Alexandre, can you try this patch with NSPR_LOG_MODULES=MediaStreamGraph:5 in your environment? It might possibly fix your bug, but I don't expect it to, but the log data would be helpful. Also, if you can get a stack for us hitting http://dxr.mozilla.org/mozilla-central/dom/camera/CameraPreview.cpp.html#l44 that would be helpful. I have absolutely no idea how we can hit that.
Assignee: nobody → roc
(Reporter)

Comment 3

5 years ago
I'll give it a try, but FYI, I'm not the only one hitting this.
(Reporter)

Comment 4

5 years ago
First, backtrace from GDB (your patch not applied):
Reading symbols from /home/alex/codaz/B2G/objdir-gecko/dist/bin/b2g...done.
Remote debugging from host 127.0.0.1
syscall () at bionic/libc/arch-arm/bionic/syscall.S:50
50	    ldmfd   sp!, {r4, r5, r6, r7}
(gdb) break CameraPreview.cpp
CameraPreview.cpp  cpp                cpp_t              
(gdb) break CameraPreview.cpp:45
Breakpoint 1 at 0x4094049e: file /home/alex/codaz/B2G/gecko/dom/camera/CameraPreview.cpp, line 45.
(gdb) continue 
Continuing.
[New Thread 77.241]
[Switching to Thread 77.241]

Breakpoint 1, CameraPreviewListener::NotifyConsumptionChanged (this=0x29ec008, aGraph=<value optimized out>, aConsuming=113)
    at /home/alex/codaz/B2G/gecko/dom/camera/CameraPreview.cpp:45
45	        state = "unknown";
(gdb) bt
#0  CameraPreviewListener::NotifyConsumptionChanged (this=0x29ec008, aGraph=<value optimized out>, aConsuming=113) at /home/alex/codaz/B2G/gecko/dom/camera/CameraPreview.cpp:45
#1  0x4094c1e6 in mozilla::MediaStreamGraphImpl::UpdateConsumptionState (this=0x20667c8, aStream=0x29ebee0) at /home/alex/codaz/B2G/gecko/content/media/MediaStreamGraph.cpp:572
#2  0x4094f8a4 in mozilla::MediaStreamGraphImpl::RunThread (this=0x20667c8) at /home/alex/codaz/B2G/gecko/content/media/MediaStreamGraph.cpp:1380
#3  0x4094faac in Run (this=<value optimized out>) at /home/alex/codaz/B2G/gecko/content/media/MediaStreamGraph.cpp:1512
#4  0x40c837fa in nsThread::ProcessNextEvent (this=0x2066898, mayWait=<value optimized out>, result=0x4ca65eb7) at /home/alex/codaz/B2G/gecko/xpcom/threads/nsThread.cpp:624
#5  0x40c63f06 in NS_ProcessNextEvent_P (thread=0xa0, mayWait=true) at /home/alex/codaz/B2G/objdir-gecko/xpcom/build/nsThreadUtils.cpp:220
#6  0x40c83c28 in nsThread::ThreadFunc (arg=<value optimized out>) at /home/alex/codaz/B2G/gecko/xpcom/threads/nsThread.cpp:257
#7  0x401909b4 in _pt_root (arg=<value optimized out>) at /home/alex/codaz/B2G/gecko/nsprpub/pr/src/pthreads/ptthread.c:156
#8  0x4004fc28 in __thread_entry (func=0x40190955 <_pt_root>, arg=0x20bc920, tls=<value optimized out>) at bionic/libc/bionic/pthread.c:217
#9  0x4004f77c in pthread_create (thread_out=<value optimized out>, attr=0xbe86c6b4, start_routine=0x40190955 <_pt_root>, arg=0x20bc920) at bionic/libc/bionic/pthread.c:357
#10 0x00000000 in ?? ()
(Reporter)

Comment 5

5 years ago
Created attachment 654576 [details] [diff] [review]
Logcat with the patch applied

With updated gecko (master at ef6746907b0a6a5d3160e1b26272ba38c5fdef73), and the proposed changes, the preview works again. Not sure if the patch is related, I'll retry without. In the meantime, please find the log with the changes applied and environment set accordingly.
(Reporter)

Comment 6

5 years ago
Please also not that during this latest trial, I had no "unknown" status popping.
(Reporter)

Comment 7

5 years ago
Build just finished, without your proposed patch and with master at ef6746907b0a6a5d3160e1b26272ba38c5fdef73, preview is broken, and I get "unknown" status in logcat.
(Reporter)

Comment 8

5 years ago
I've played a bit with gdb, and adding a breakpoint in MediaStreamGraphImpl::UpdateConsumptionState() inside the "if (state != aStream->mLastConsumptionState)" is never being hit. Meaning state == aStream->mLastConsumptionState.
(Reporter)

Comment 9

5 years ago
And I see nowhere in the sourcecode where aStream->mLastConsumptionState is changed.
(Reporter)

Comment 10

5 years ago
Also, playing with breakpoints, I saw that both "aStream->mIsConsumed = true;" in MediaStreamGraphImpl::DetermineWhetherStreamIsConsumed gets called.
(Reporter)

Comment 11

5 years ago
Issue is fixed by only applying this part of your patch:

@@ -940,16 +939,17 @@ void
 MediaStreamGraphImpl::UpdateStreamOrder()
 {
   nsTArray<nsRefPtr<MediaStream> > oldStreams;
   oldStreams.SwapElements(mStreams);
   for (PRUint32 i = 0; i < oldStreams.Length(); ++i) {
     MediaStream* stream = oldStreams[i];
     stream->mHasBeenOrdered = false;
     stream->mKnowIsConsumed = false;
+    stream->mIsConsumed = false;
     stream->mIsOnOrderingStack = false;
     stream->mInBlockingSet = false;
     ProcessedMediaStream* ps = stream->AsProcessedStream();
     if (ps) {
       ps->mInCycle = false;
     }   
   }
(In reply to Alexandre LISSY from comment #11)
> Issue is fixed by only applying this part of your patch:
> 
> @@ -940,16 +939,17 @@ void
>  MediaStreamGraphImpl::UpdateStreamOrder()
>  {
>    nsTArray<nsRefPtr<MediaStream> > oldStreams;
>    oldStreams.SwapElements(mStreams);
>    for (PRUint32 i = 0; i < oldStreams.Length(); ++i) {
>      MediaStream* stream = oldStreams[i];
>      stream->mHasBeenOrdered = false;
>      stream->mKnowIsConsumed = false;
> +    stream->mIsConsumed = false;
>      stream->mIsOnOrderingStack = false;
>      stream->mInBlockingSet = false;
>      ProcessedMediaStream* ps = stream->AsProcessedStream();
>      if (ps) {
>        ps->mInCycle = false;
>      }   
>    }

I can confirm that this patch fixes a lot of problems (previews shutdown properly and objects are properly collected when the camera is closed); but I'm still seeing the preview stall eventually--all of the GraphicsLockedBuffers seem to be stuck in the DEQUEUED or RENDERING state.
(In reply to Alexandre LISSY from comment #4)
> (gdb) bt
> #0  CameraPreviewListener::NotifyConsumptionChanged (this=0x29ec008,
> aGraph=<value optimized out>, aConsuming=113) at
> /home/alex/codaz/B2G/gecko/dom/camera/CameraPreview.cpp:45
> #1  0x4094c1e6 in mozilla::MediaStreamGraphImpl::UpdateConsumptionState
> (this=0x20667c8, aStream=0x29ebee0) at
> /home/alex/codaz/B2G/gecko/content/media/MediaStreamGraph.cpp:572

I guess the compiler is optimizing mIsConsumed ? CONSUMED : NOT_CONSUMED away to nothing since the only valid values for mIsConsumed are 0 and 1, so uninitialized and invalid mIsConsumed is passed through.

Thanks a ton for your help.
Created attachment 654852 [details] [diff] [review]
fix
Attachment #654506 - Attachment is obsolete: true
Attachment #654852 - Flags: review?(rjesup)
Assignee: roc → nobody
Component: General → Video/Audio
Product: Boot2Gecko → Core
Assignee: nobody → roc
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #13)
> (In reply to Alexandre LISSY from comment #4)
> > (gdb) bt
> > #0  CameraPreviewListener::NotifyConsumptionChanged (this=0x29ec008,
> > aGraph=<value optimized out>, aConsuming=113) at
> > /home/alex/codaz/B2G/gecko/dom/camera/CameraPreview.cpp:45
> > #1  0x4094c1e6 in mozilla::MediaStreamGraphImpl::UpdateConsumptionState
> > (this=0x20667c8, aStream=0x29ebee0) at
> > /home/alex/codaz/B2G/gecko/content/media/MediaStreamGraph.cpp:572
> 
> I guess the compiler is optimizing mIsConsumed ? CONSUMED : NOT_CONSUMED
> away to nothing since the only valid values for mIsConsumed are 0 and 1, so
> uninitialized and invalid mIsConsumed is passed through.
> 
> Thanks a ton for your help.

Unfortunately even with this patch, the preview still freezes.

I've been instrumenting a lot of the code, and from what I can see, it looks like something gets confused in an upper layer.  The camera is blocked because there are no free buffers--all of the buffers are either DEQUEUED or RENDERING, which means they're either already in the pipe to be filled, or displayed, respectively.  A call to the GonkIOSurfaceImage dtor will mark the buffers FREE, but that never happens.  Meanwhile the media thread keeps on chugging (it sure does generate a lot of output. :)

I have a _very_ detailed log that shows what's going on, but it's 15MiB.

It prompts two questions:
1. Why is the camera holding onto so many buffers?
2. Why is media stream/renderer not consuming and releasing the frames?

This pastie shows a backtrace of what should be happening: http://pastebin.com/DieGstPZ
blocking-basecamp: --- → +
Created attachment 655645 [details]
Detailed log dump

Shows:
1. open camera app, which opens preview successfully
2. takes picture
3. restarts preview successfully
4. takes pictures
5. preview fails to restart
I've confirmed that if ReceiveFrame() is replaced with a stub that just immediately frees the preview data buffer, the preview never freezes.
The patch on this bug is waiting for 6 days now for review. Is it not the right approach, or still valid fix? Does something else need to happen per Mike's previous comments?
That patch needs to land. I just nagged Jesup.
(In reply to Mike Habicher [:mikeh] from comment #16)
> Shows:
> 1. open camera app, which opens preview successfully
> 2. takes picture
> 3. restarts preview successfully
> 4. takes pictures
> 5. preview fails to restart

In that log, only three frames get written to the final stream 4538c3d0. Are we really expecting to have only three frames available? Have we failed to free frames from the previous stream(s)?
We remove media stream 4538d920 from the graph only after 50 seconds, which is after the hang and long after we stopped using it. So maybe it (and 4655c240) have kept some Images alive. They probably aren't removed from the graph until cycle collection (or at least GC) runs, and maybe they aren't running very often here. Not sure yet if that's the problem, although since each stream holds onto at least the last Image, it's not good.

I see that at about 1.8 seconds (right after "Updating current time to ... real 1.752319") we suddenly allocate all available buffers (according to your "Buffer [0]: state DEQUEUED" logs, before time 1.806122. Why is that? That's less than 50ms so you should only get a couple of frames in that time?
(Reporter)

Comment 22

5 years ago
With patch from bug 781892, I've been able to go up to 10 photos before getting killed (OOM probably)
Comment on attachment 654852 [details] [diff] [review]
fix

Review of attachment 654852 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry for the delay; I got swamped in bugmail by some QA add-myself-to-bugs and triage-generated mails, and haven't dug out, and missed this one
Attachment #654852 - Flags: review?(rjesup) → review+
I think we should consider this bug fixed by this patch. The problem with playback stalling is a different problem that deserves its own bug.
Comment on attachment 654852 [details] [diff] [review]
fix

Review of attachment 654852 [details] [diff] [review]:
-----------------------------------------------------------------

Fixes a serious regression introduced before the Aurora uplift.
Attachment #654852 - Flags: approval-mozilla-aurora?
(Reporter)

Comment 26

5 years ago
Yep, the freeze is being tracked down in bug 781892.
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #25)
> Comment on attachment 654852 [details] [diff] [review]
> fix
> 
> Review of attachment 654852 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Fixes a serious regression introduced before the Aurora uplift.

I don't see a comment for this landing on central yet, will wait for that to approve aurora uplift.
https://hg.mozilla.org/mozilla-central/rev/3d7e89acf4c2
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla18
Duplicate of this bug: 786081

Updated

5 years ago
QA Contact: jsmith
Whiteboard: [qa+]

Updated

5 years ago
Whiteboard: [qa+] → [qa+], [getUserMedia], [blocking-gum+]
Verified on 8/30 Nightly build.
Status: RESOLVED → VERIFIED
Whiteboard: [qa+], [getUserMedia], [blocking-gum+] → [qa!], [getUserMedia], [blocking-gum+]
Attachment #654852 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
https://hg.mozilla.org/releases/mozilla-aurora/rev/f9cafaf42af2
status-firefox17: --- → fixed
You need to log in before you can comment on or make changes to this bug.