Closed Bug 881584 Opened 7 years ago Closed 7 years ago

[A/V] Background activity keep consuming power when Youtube is paused by power button.

Categories

(Firefox OS Graveyard :: Gaia::Video, defect, P1)

ARM
Gonk (Firefox OS)

Tracking

(blocking-b2g:leo+, b2g18 fixed, b2g-v1.1hd fixed)

RESOLVED FIXED
1.1 QE3 (26jun)
blocking-b2g leo+
Tracking Status
b2g18 --- fixed
b2g-v1.1hd --- fixed

People

(Reporter: leo.bugzilla.gecko, Assigned: alive)

References

Details

Attachments

(9 files)

Precondition : Device is connected by 3G.

STR
1. Play youtube
2. push power button

Then, something periodically wake up in background.
It consumes useless power.

This problem may be related to Bug 870564.
Please check attached file (graph) to compare before and after patch from Bug 870564.
blocking-b2g: --- → leo?
Blocks: 877024
How can we find out what's waking up?
Attachment #761331 - Attachment description: cpu profiler after youtube play and power button → cpu profiler after starting browser and power button
Attachment #761331 - Attachment filename: Youtube&powerkey.log → JustBrowser.log
Attachment #761333 - Attachment description: cpu profiling → cpu profiling after youtube playing and power button
Attachment #761333 - Attachment filename: Browser.log → youtube.log
Attachment #761331 [details] : CPU profiling data of this problem.
Attachment #761333 [details] : CPU profiling data after starting browser and pushing power button.

I got this data for 5~6 minutes after push power button.
As you know, it's a list of all process that is executed in idle state.

I found some differences between two.

Is it possible to find any clue by these data?
It's hard for me to tell :-(.

I don't understand this output very well. Is it possible to distinguish the browser process from the b2g process? How about the mediaserver process? I can only see the "b2g app" here.
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #6)
> It's hard for me to tell :-(.
> 
> I don't understand this output very well. Is it possible to distinguish the
> browser process from the b2g process? 
hmm...I don't know how can I distinguish it.
It just list up the all process that spends tick in certain period.

> How about the mediaserver process? I can only see the "b2g app" here.
I think mediaserver process is not activated after push power button. That's why it doesn't appear.

As I mentioned above, I got this record after push power button.
So any processes appeared in the list means that they are in executing state more than once in a certain period.
Each process/thread is separated by dashed line.
And the between dashed line, it means call stack of the process.

How about check Attachment #761333 [details],
from line 2931, it's totally different with other idle case.
And almost last of the line, there are some logs from httmchannelchild.
By comparing attachment 761331 [details] and attachment 761333 [details], there are a lot of http related function in youtube case. Does "b2g" means both "b2g" and "plugin-container" process?
See Also: → 880144
The call graphs in the profiling results looked not good. Was this compiled in arm mode with certain gcc options(e.g. -fno-omit-frame-pointer, -mapcs-frame) on? AFAIK oprofile won't produce correct call graphs in thumb/thumb2 mode.
Priority: -- → P1
Target Milestone: --- → 1.1 QE3 (24jun)
To speed up problem diagnosis, would you please provide the following information after problem reproduction?
- adb logcat with threadtime
- dmesg
- Is this problem only with 3G connection? Did you see the same problem if you used wifi?
Flags: needinfo?(leo.bugzilla.gecko)
Priority: P1 → --
Target Milestone: 1.1 QE3 (24jun) → ---
Recover accidentally cleared flags.
Priority: -- → P1
Target Milestone: --- → 1.1 QE3 (24jun)
Initially we suspected that this is caused by "the hack of allowing normal channel to play during screen off" but we found the video is playing by video app and it used content channel.

  1. Video app will listen visibilitychange event and stop to play when screen is off.
     And I saw "OMX AAC component destroyed" appeared from logcat also "omx.xxx.video.xxx: stopped in state 1".
  2. From dmesg log, I found there is a wakup event called "wakeup wake lock: DATA5" which is fired about every 54 seconds.

The strange thing I see is that when video is playing and I pressed the power key:
  Video app: I can't see "Media State" & "OMXDecoder" threads via "b2g-ps -t"

  Youtube -> Video app: I can see "Media State" & "OMXDecoder".

It seems there are two cases on video app during screen off.
Flags: needinfo?(leo.bugzilla.gecko)
attachment 765216 [details] : Result by same STR via wifi

While play, if I push home button and power button, it looks file.
Please refer this attachment 765217 [details].
Hi David,

According to comment 12 & 15, could you give some suggestions on these strange things? Additionally there is a question here.

Q1: Does mozAudioChannelType used by video and youtube are all "content" channel?
Q2: comment 12
Q3: What is the difference between "screen off" and "back to homescreen" during playing video? (comment 15)

Thanks.
Flags: needinfo?(dflanagan)
Assignee: nobody → rlin
blocking-b2g: leo? → leo+
Mike: the original reporter of this bug thinks that it might have something to do with bug 870564. Any ideas?  I'm not sure why no one asked you at the start.
Flags: needinfo?(dflanagan) → needinfo?(mhabicher)
(In reply to Marco Chen [:mchen] from comment #16)
> Hi David,
> 
> According to comment 12 & 15, could you give some suggestions on these
> strange things? Additionally there is a question here.
> 
> Q1: Does mozAudioChannelType used by video and youtube are all "content"
> channel?

Yes. See view.js:112:

      dom.player.mozAudioChannelType = 'content';


> Q2: comment 12

The video app runs completely different code when invoked as an activity (to play a youtube video), so yes, there are two different cases.  As a normal app, it monitors mozvisibilitychange events.  When invoked as an activity it does not listen for those events.  However, as an inline activity, the app gets killed (I think) if the user taps the power button or the Home button.  If I do either of those things I go back to the browser app, so I would expect that the playing video and all of its resources would be deallocated in that case, but maybe not?

> Q3: What is the difference between "screen off" and "back to homescreen"
> during playing video? (comment 15)

For the normal video app itself, I don't think there is any difference: both cause a mozvisibilitychange event and the app explicitly stops playing the video and even unloads it.

When running as an activity, however, both of those actions cause the activity to end and the video app to exit. Alive or Tim might know more about exactly what happens to an activity when you press one of those buttons.

> 
> Thanks.
(In reply to David Flanagan [:djf] from comment #17)
>
> Mike: the original reporter of this bug thinks that it might have something
> to do with bug 870564. Any ideas?  I'm not sure why no one asked you at the
> start.

If this is on m-c (I don't see which branch this is for) the patch in bug 870564 seems to include extra calls to |mEventQ->Resume();|, which might be the cause of the extra power consumption.

jduell, what do you think?
Flags: needinfo?(mhabicher) → needinfo?(jduell.mcbugs)
(In reply to leo.bugzilla.gecko from comment #0)
> Created attachment 760713 [details]
> Power consumption graph after patch from Bug 870564
> 
> Precondition : Device is connected by 3G.
> 
> STR
> 1. Play youtube
> 2. push power button

Hi Leo, did the STR use gaia's Video app for playback? If it is the case, the video app is closed when "2. push power button" on MozBuild ROM. Can you confirm it on your ROM?

As other STR, there is a packaged app in bug 877024.
(In reply to David Flanagan [:djf] from comment #18)
> When running as an activity, however, both of those actions cause the
> activity to end and the video app to exit. Alive or Tim might know more
> about exactly what happens to an activity when you press one of those
> buttons.

Hi David,

After unlocking lock screen I didn't see video app as activity when playing youtube be closed after pressing power button and pressing again to "screen on" state. 

Hi Alive,

As David said, if video app as activity can be closed/existed when playing youtube then I think it would be the case like normal video app and no additional power there (even there is a bug). Is there a bug so I still see video app as activity after unlocking screen? Thanks.
Flags: needinfo?(alive)
> If this is on m-c (I don't see which branch this is for) the patch in bug 870564 seems to 
> include extra calls to |mEventQ->Resume();|, which might be the cause of the extra 
> power consumption.

I think it's very unlikely that those changes are causing this.  That patch just moved some APIs around--it's not actually doing a logical resume that didn't exist before.
Flags: needinfo?(jduell.mcbugs)
(In reply to Sotaro Ikeda [:sotaro] from comment #20)
> (In reply to leo.bugzilla.gecko from comment #0)
> > Created attachment 760713 [details]
> > Power consumption graph after patch from Bug 870564
> > 
> > Precondition : Device is connected by 3G.
> > 
> > STR
> > 1. Play youtube
> > 2. push power button
> 
> Hi Leo, did the STR use gaia's Video app for playback? If it is the case,
> the video app is closed when "2. push power button" on MozBuild ROM. Can you
> confirm it on your ROM?
> 
> As other STR, there is a packaged app in bug 877024.
Every result of which I have tested, is by browser app.
If needed, I will check it by youtube app and give a result herr.
(In reply to Marco Chen [:mchen] from comment #21)
> (In reply to David Flanagan [:djf] from comment #18)
> > When running as an activity, however, both of those actions cause the
> > activity to end and the video app to exit. Alive or Tim might know more
> > about exactly what happens to an activity when you press one of those
> > buttons.
> 
> Hi David,
> 
> After unlocking lock screen I didn't see video app as activity when playing
> youtube be closed after pressing power button and pressing again to "screen
> on" state. 
> 
> Hi Alive,
> 
> As David said, if video app as activity can be closed/existed when playing
> youtube then I think it would be the case like normal video app and no
> additional power there (even there is a bug). Is there a bug so I still see
> video app as activity after unlocking screen? Thanks.


Currently the life cycle of inline activity window is:

1. Opened by one app
2. Closed if screen is locked(will be resolved in bug 880588)
3. Closed if app switching occurs
4. Closed if home button pressed
5. Closed if activity opened is closed/crashed.
6. Closed if activity itself is crashed.
7. Closed if activity do postError or postResult.

In your case I think it's a bug but wont' be a bug after bug 880588 resolved.

My question:
If I set the visibility of the inline activity frame to false when screen is locked,
does this resolve this bug? Could video/youtube app use visibilitychange to know it's background and stop consuming power?
Flags: needinfo?(alive)
Hi Leo,

Q1:
According to this bug is related to device on suspend state, it is hard to collect log from USB for adb logcat or dmesg. Could you help to get the kernel log from UART port especially when device hit the strange battery current status? I think it is the only way we can get some log from UART port.

Thanks.
Flags: needinfo?(leo.bugzilla.gecko)
Hi Leo,
Do you know how to disable the battery check (or other reason?)
I use power monitor and only attach the +- pin, It works and get the similar result.
But when I plug the USB line into device, I got reboot.
Oh, It seems I need to rework the device's battery and work around this problem.
BTW, Hi Leo, could to also help to measure the A cpu0's clock and make sure it cause by core process?
(match the timestamp between the cpu's clk and power consumption)
It's interesting that the peak is near 150ma.
Attached file logcat on device
I found this problem may casue by RIL get message and trigger the b2g process.
03-06 22:30:03.790 I/Diag_Lib(  155): rpc_handle_rpc_call: for Xid: 119, Prog: 31000000, Vers: d17ed9ea, Proc: 00000014
...
03-06 22:30:06.632 D/        (  152): [FASTDORMANCY] timeCount : 0sec, TriggerTime : 5sec

03-06 22:30:39.000 D/QCRIL_RPC(  155): Enter qcril_cm_srvsys_event_callback
..
03-06 22:30:46.600 I/ONCRPC  (  155): oncrpc_proxy_handle_cmd_rpc_call: Dispatch returned for xid: 131

BTW, you can run background logcat process to log the device log when you perform this test.
Hi Randy, 
Thank you for checking this.

I doubt that we can only reproduce this on our ROM. 
Leo will check that. If so, We can close this bug.
(In reply to Randy Lin [:rlin] from comment #28)
> Created attachment 767113 [details]
> logcat on device
> 
> I found this problem may casue by RIL get message and trigger the b2g
> process.
> 03-06 22:30:03.790 I/Diag_Lib(  155): rpc_handle_rpc_call: for Xid: 119,
> Prog: 31000000, Vers: d17ed9ea, Proc: 00000014
> ...
> 03-06 22:30:06.632 D/        (  152): [FASTDORMANCY] timeCount : 0sec,
> TriggerTime : 5sec
> 
> 03-06 22:30:39.000 D/QCRIL_RPC(  155): Enter qcril_cm_srvsys_event_callback
> ..
> 03-06 22:30:46.600 I/ONCRPC  (  155): oncrpc_proxy_handle_cmd_rpc_call:
> Dispatch returned for xid: 131
> 
> BTW, you can run background logcat process to log the device log when you
> perform this test.

Before I ask the log to RIL engineer, do you have any idea why it doesn't occur if you exit youtube by home button?
Flags: needinfo?(leo.bugzilla.gecko)
Sorry..
Forget the last comment, RIL team already checked the problem :)
The RIL may be the trigger and wake-up b2g process, not the root-casue.
I try to use top command to check which threads is consuming the cpu, 
Found the b2g thread is more likely doing SOMETHING at that point.
Still under investing.
Found tcp network activity during the high power consumption. 
Just Send/Rcv few package during this timestamp

15:27:54.820518 IP 203-66-48-223.HINET-IP.hinet.net.www > 111.80.220.196.58017: . ack 1120 win 16 <nop,nop,timestamp 292768938 7594>
15:27:54.820781 IP 111.80.220.196.58017 > 203-66-48-223.HINET-IP.hinet.net.www: . ack 4737692 win 0 <nop,nop,timestamp 19920 292732018>

The 111.80.220.196 is youtube stream server,
So the story I think is
1. power power key and let youtube in foreground
2. device enter suspend
3. RIL notify network connection speed from H(HSDPA)->3G(WCDMA) or RIL others unsolicited commands, then device wake-up.
5. Video apps try to streaming again, affect the 3g connection speed (3G->H).
Loop 2. 

Press home key seems stop the app and can't found any network activity.

Hi Leo, Could you confirm the RIL status change?
Leo, your build seems strange to me.
What's the gaia commit hash?

I think this won't happen (locked but inline activity aren't removed.) if you use the lastest v1-train.

But anyway, this behavior would be changed by bug 880588.

David, according to Randy, the video inline activity is trying to connect to youtube when screen is locked(visibilitychange->false). I think a proper fix here is to (1) close itself when visibility is changed or (2) try not to connect(but I don't know how) when visibility is hidden.

And if youtube "APP" (not inline activity) has the same behavior, we should notify youtube to have a fix about this..
Flags: needinfo?(leo.bugzilla.gecko)
See last comment.
Flags: needinfo?(dflanagan)
After referring to Randy, I could tell the real problem here is:
Any app tries to connect Internet via 3G or wifi(IF-AND-ONLY-IF wifi is not turned off when screen is off) would repro this. (Connected network would wake up the device and causes what you see in the power consumption graph.)

Does this need to be resolved in app level(gaia)? If there's an app that set an interval to fetch remote data, same thing would happen.
(In reply to Alive Kuo [:alive] from comment #34)
> Leo, your build seems strange to me.
> What's the gaia commit hash?
> 
> I think this won't happen (locked but inline activity aren't removed.) if
> you use the lastest v1-train.
> 
> But anyway, this behavior would be changed by bug 880588.
> 
> David, according to Randy, the video inline activity is trying to connect to
> youtube when screen is locked(visibilitychange->false). I think a proper fix
> here is to (1) close itself when visibility is changed or (2) try not to
> connect(but I don't know how) when visibility is hidden.
> 
> And if youtube "APP" (not inline activity) has the same behavior, we should
> notify youtube to have a fix about this..

Alive and Randy:

Would it be enough to have the apps/video/js/view.js listen for mozvisibilitychange events and pause playback when hidden?

I don't think we should attempt to abort an XHR (to youtube) in progress on visibility change and I suspect that the logic for restarting an XHR would be hard to get right.  But we certainly shouldn't be attempting to play a video if the activity is not visible.

It should be pretty easy to write a patch to do this. I'm happy to review one, or I can write it if that would help.

The other video-playing apps (Gallery and Camera) might not have the same problem. Video runs completely separate code when invokved as an activity which is the problem here.  Gallery probably already has a visibility change handler.  And the Camera app doesn't allow video playback when invoked as an activity, I think.
Flags: needinfo?(dflanagan)
(In reply to David Flanagan [:djf] from comment #37)
> (In reply to Alive Kuo [:alive] from comment #34)
> > Leo, your build seems strange to me.
> > What's the gaia commit hash?
> > 
> > I think this won't happen (locked but inline activity aren't removed.) if
> > you use the lastest v1-train.
> > 
> > But anyway, this behavior would be changed by bug 880588.
> > 
> > David, according to Randy, the video inline activity is trying to connect to
> > youtube when screen is locked(visibilitychange->false). I think a proper fix
> > here is to (1) close itself when visibility is changed or (2) try not to
> > connect(but I don't know how) when visibility is hidden.
> > 
> > And if youtube "APP" (not inline activity) has the same behavior, we should
> > notify youtube to have a fix about this..
> 
> Alive and Randy:
> 
> Would it be enough to have the apps/video/js/view.js listen for
> mozvisibilitychange events and pause playback when hidden?
> 

Yes, I think this is a correct direction to go.
Every inline activity should utilize visibilitychange event to narrow down the resource consumption if necessary.

Leo, how abou this solution? I think David is right that activity of camera and gallery won't consume additional power when screen is off and if they're not removed.
Patch v1: Stop activity when visibility is hidden.

David,

The patch is based on bug 880588's patch.(It's not merged yet so.)
I try to pause the video but tcpdump tells me it's still trying to connect network.
I think the correct way is to reset video src if we want to keep the video, but this needs too more work to go IMO. (reset the src...reset mozAudioChannel...etc) So the most simple way is just stop the activity if we're playing youtube video and the visibility is changed to be hidden.

I could revise the patch to reset the src and redo player initilization if you think you want to keep the activity alive anyway.
Attachment #768144 - Flags: review?(dflanagan)
Comment on attachment 768144 [details]
https://github.com/mozilla-b2g/gaia/pull/10652

The solution (stop the activity when the screen is locked) is fine with me because that is the behavior we've had all along.

I am a little concerned about our inability to distinguish the user locking the screen from the screen timing out.

Now that the video app does not have an explicit wake lock (because of bug 868325) is it possible that the screen could time out while connecting to youtube server (over a slow data connection) before the video has started playing? If so, then the screen blanking would cause mozvisibilitychange and the activity would abort.

Similarly, what if the users starts watching a video, then pauses the video and the screen blanks because of a timeout.  What would happen in that case before bug 880548? Would that abort the activity?  It seems like the user would be upset to find that when they turn the screen back on their video is gone. If they paused it, they expect to be able to resume it.

But if that is already the current behavior, then let's just land this patch, since it won't change any behavior, and then file a followup bug to make it smarter and allow resuming a paused video (video.js has a pair of functions releaseVideo() and restoreVideo() that show how this can be done).
Attachment #768144 - Flags: review?(dflanagan) → review+
(In reply to David Flanagan [:djf] from comment #40)
> Comment on attachment 768144 [details]
> https://github.com/mozilla-b2g/gaia/pull/10652
> 

I am a little confused by the 'blank' wording, but if that happens it sounds a bug.
As you said that the original UX is not good, so let's manipulate it in a followup bug.
Assignee: rlin → alive
master
https://github.com/mozilla-b2g/gaia/commit/d199ea0404b04baf91186ac63cff33d52267b18c


v1-train
https://github.com/mozilla-b2g/gaia/commit/f54b1944d52ae48b8212e3eae13c6f11c2cd641b
Status: NEW → RESOLVED
Closed: 7 years ago
Component: General → Gaia::Video
Flags: needinfo?(leo.bugzilla.gecko)
Resolution: --- → FIXED
v1.1.0hd: f54b1944d52ae48b8212e3eae13c6f11c2cd641b
v1.1.0hd: 9873bb9917cd81e271498cc28b931b9b3855580f
You need to log in before you can comment on or make changes to this bug.