1119714 - [FFOS7715 v2.1][dolphin][Flame]Sometimes 720P video cannot be played in video app after backing from dormant state

Status: RESOLVED DUPLICATE of bug 1112410

Description

[[e-mail]]

DEFECT DESCRIPTION:
  When playing music, 720P video cannot playing in video app.

Steps to reproduce:
----------------------------------------------------
Step 1: Playing a 720P video in video app.
Step 2: click home button back to homescreen.
Step 3: open music app, and select one music to playing.
Step 4: click home button back to homescreen.
Step 5: Open video app which hide in back ground.
Step 6: Video app display a black screen, click playing button, video cannot be play.

Additional info:
--------------------------------------
Video demation:1280x720
Reproduce rate: 3/5

Comment 1

[[e-mail]]

Created attachment 8546500 [details]
video_cannot_play.log

Issue log file.

Comment 2

[[e-mail]]

In log file, I found the following logs:

> 01-09 03:42:11.533 V/OMXCodec( 3509): [OMX.google.aac.decoder] OMX_EventPortSettingsChanged(port=1, 
> data2=0x00000000)
> 01-09 03:42:11.533 V/OMXCodec( 3509): [OMX.google.aac.decoder] PORT_SETTINGS_CHANGED(1)
> 01-09 03:42:11.533 V/OMXCodec( 3509): [OMX.google.aac.decoder] sending OMX_CommandPortDisable(1)
> 01-09 03:42:11.533 V/OMXCodec( 3509): [OMX.google.aac.decoder] FILL_BUFFER_DONE(buffer: 0xb07e86a0, 
> size: 0, flags: 0x00000000, timestamp: 0 us (0.00 secs))
> 01-09 03:42:11.533 V/OMXCodec( 3509): [OMX.google.aac.decoder] Port is disabled, freeing buffer 
> 0xb07e86a0
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] FILL_BUFFER_DONE(buffer: 0xb07e8790, 
> size: 0, flags: 0x00000000, timestamp: 0 us (0.00 secs))
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Port is disabled, freeing buffer 
> 0xb07e8790
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] FILL_BUFFER_DONE(buffer: 0xb07e87e0, 
> size: 0, flags: 0x00000000, timestamp: 0 us (0.00 secs))
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Port is disabled, freeing buffer 
> 0xb07e87e0
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] FILL_BUFFER_DONE(buffer: 0xb07e8880, 
> size: 0, flags: 0x00000000, timestamp: 0 us (0.00 secs))
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Port is disabled, freeing buffer 
> 0xb07e8880
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] PORT_DISABLED(1)
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] sending OMX_CommandPortEnable(1)
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] allocating 4 buffers of size 24576 on > output port
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] allocated buffer 0xb07e8790 on output > port
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] allocated buffer 0xb07e87e0 on output > port
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] allocated buffer 0xb07e8880 on output > port
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] allocated buffer 0xb07e8c40 on output > port
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] PORT_ENABLED(1)
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Calling fillBuffer on buffer 0xb07e8790
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Calling fillBuffer on buffer 0xb07e87e0
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Calling fillBuffer on buffer 0xb07e8880
> 01-09 03:42:11.543 V/OMXCodec( 3509): [OMX.google.aac.decoder] Calling fillBuffer on buffer 0xb07e8c40

Dear Vchen:

According to the above log, please help to check this issue.
Thanks a lot.

Comment 3

[[e-mail]]

In OMXCodec.h:
>    enum {
>       kPortIndexInput  = 0,
>       kPortIndexOutput = 1
>   };

According to the issue log, buffers port of kPortIndexOutput seems disabled， I don't know what happend about this, so I want to your support!
Thanks!

Comment 4

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Lin Hui -

Two questions for you:

1. Can you reproduce this on Flame?(please try both single core and dual core)

2. Could you also upload the 720P video you used into some free space(e.g. Baidu..) such that we can download and try to reproduce this issue at our end?

Thanks

Comment 5

[[e-mail]]

(In reply to Vance Chen [:vchen][[e-mail]] from comment #4)
> 1. Can you reproduce this on Flame?(please try both single core and dual
> core)
I find another way to reproduce this issue both in flame & dolphin, this case, flame is dual core.
STR:
1.Let the Screen lock disabled.
2.Playing 720P video in video app.
3.Press power button to let the screen goes dark
4.Repress power button to light up the screen
5.click playing button to play video.
6.video cannot be playing.

The probability of flame is lower than dolphin.

> 2. Could you also upload the 720P video you used into some free space(e.g.
> Baidu..) such that we can download and try to reproduce this issue at our
> end?
video source are in blow site:
   http://pan.baidu.com/s/1eQGiLFG

Thank you.

Comment 6

[[e-mail]]

Created attachment 8547275 [details]
flame.log

Using new test step, flame are also cannot playing video.

ps:low probability on flame, high probability on dolphin.

Comment 7

[Vincent Liu[:vliu]]

Hi Steven,

As talked, would you please have a look? Thanks

Comment 8

[StevenLee[:slee]]

Hi Blake,

Can you verify what the problem is? Thanks.

Comment 9

[[e-mail]]

Hi All:

After video app re-back to the foreground, it's will started with a seek, if seek completed, firing a seek-completed event, then video can go on playing, but if during a long seek, the audio seek isn't completed.

video can play logs are as follows:
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 
>> vqFin=0 vqSz=1
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=0 
>> aqFin=0 aqSz=0
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): CheckIfSeekComplete() audioSeekComplete=0 
>> videoSeekComplete=1
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): OmxDecoder::Play
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 
>> vqFin=0 vqSz=1
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=0 
>> aqFin=0 aqSz=0
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): CheckIfSeekComplete() audioSeekComplete=0 
>> videoSeekComplete=1
>> 01-12 03:22:12.430 I/lin.hui ==>(  668): OmxDecoder::Play
>> 01-12 03:22:12.440 I/lin.hui ==>(  668): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 
>> vqFin=0 vqSz=1
>> 01-12 03:22:12.440 I/lin.hui ==>(  668): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=0 
>> aqFin=0 aqSz=1
>> 01-12 03:22:12.440 I/lin.hui ==>(  668): CheckIfSeekComplete() audioSeekComplete=1 
>> videoSeekComplete=1
>> 01-12 03:22:12.440 I/lin.hui ==>(  668): In SeekCompleted-->RenderVideoFrame 

but if seek not completed, the log like this:
>> 01-12 03:22:21.450 I/lin.hui ==>(  668): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 
>> vqFin=0 vqSz=0
>> 01-12 03:22:21.450 I/lin.hui ==>(  668): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=1 
>> aqFin=0 aqSz=0
>> 01-12 03:22:21.450 I/lin.hui ==>(  668): CheckIfSeekComplete() audioSeekComplete=0 
>> videoSeekComplete=0
>> 01-12 03:22:21.450 I/lin.hui ==>(  668): OmxDecoder::Play
>> 01-12 03:22:21.460 I/lin.hui ==>(  668): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 
>> vqFin=0 vqSz=0
>> 01-12 03:22:21.460 I/lin.hui ==>(  668): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=1 
>> aqFin=0 aqSz=0
>> 01-12 03:22:21.460 I/lin.hui ==>(  668): CheckIfSeekComplete() audioSeekComplete=0 
>> videoSeekComplete=0
>> 01-12 03:22:21.460 I/lin.hui ==>(  668): OmxDecoder::Play
>> 01-12 03:22:21.480 I/lin.hui ==>(  668): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 
>> vqFin=0 vqSz=1
>> 01-12 03:22:21.480 I/lin.hui ==>(  668): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=1 
>> aqFin=0 aqSz=0
>> 01-12 03:22:21.480 I/lin.hui ==>(  668): CheckIfSeekComplete() audioSeekComplete=0 
>> videoSeekComplete=1

If "aqSz" or "vqSz" > 0, the think it's seek completed, according the log, audio seek is not completed, cause the video cannot be played?

BTW, in MediaDecoderStateMachine.cpp:
>> void MediaDecoderStateMachine::DecodeSeek()
>> {
>>  // During the seek, don't have a lock on the decoder state,
>>  // otherwise long seek operations can block the main thread.
Is the long seek operations block the main thread?

Comment 10

[Blake Wu [:bwu][:blakewu]]

I can repro this problem on my V2.1 Flame and start to investigate this bug.

Comment 11

[[e-mail]]

Dear Black:
When video app re-back to foreground, they should call EnsureAudioDecodeTaskQueued, and succeed to dispatch the DecodeAudio task, but most of time they do not dispatch the decodeaudio task successfully， cause the audio data do not decoded, followed the audioSeekComplete = 0, then can not fire the SeekCompleted task.

succeed:
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): Changed state from DECODING_METADATA to DECODING!
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 4
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 5
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): DecodeSeek: seekTime:110326000
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): mCurrentTimeBeforeSeek = 0
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): needToDecodeAudio = 0
>> 01-12 23:43:27.363 I/lin.hui ==>( 1826): MediaDecoder::SeekingStarted
>> 01-12 23:43:27.373 I/lin.hui ==>( 1826): OmxDecoder::Play
>> 01-12 23:43:27.373 I/lin.hui ==>( 1826): OmxDecoder::Play
>> 01-12 23:43:27.433 I/lin.hui ==>( 1826): needToDecodeAudio = 1
>> 01-12 23:43:27.433 I/lin.hui ==>( 1826): MediaDecoderStateMachine::EnsureAudioDecodeTaskQueued
>> 01-12 23:43:27.433 I/lin.hui ==>( 1826): dispatch DecodeAudio task starting
>> 01-12 23:43:27.433 I/lin.hui ==>( 1826): dispatch DecodeAudio task succeed
>> 01-12 23:43:27.433 I/lin.hui ==>( 1826): In DecodeAudio: mReader->RequestAudioData() mState:5


failed:
>> 01-12 23:32:23.273 I/lin.hui ==>( 1826): Changed state from DECODING_METADATA to DECODING!
>> 01-12 23:32:23.273 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 4
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 5
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): DecodeSeek: seekTime:90344000
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): mCurrentTimeBeforeSeek = 0
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): needToDecodeAudio = 0
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): MediaDecoder::SeekingStarted
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): OmxDecoder::Play
>> 01-12 23:32:23.283 I/lin.hui ==>( 1826): OmxDecoder::Play
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): needToDecodeAudio = 1
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): MediaDecoderStateMachine::EnsureAudioDecodeTaskQueued
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 vqFin=0 vqSz=0
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=1 aqFin=0 aqSz=0
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): MediaDecoderStateMachine::EnsureAudioDecodeTaskQueued
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): CheckIfSeekComplete() audioSeekComplete=0 videoSeekComplete=0
>> 01-12 23:32:23.343 I/lin.hui ==>( 1826): OmxDecoder::Play

I guess there may have something block the audio decoded.

Comment 12

[jinchao.wang]

(In reply to Blake Wu [:bwu][:blakewu] from comment #10)
> I can repro this problem on my V2.1 Flame and start to investigate this bug.

Hi  Blake Wu:
    This bug can reproduce easily in the steps of comment 5 on sprd7715ea and flame. We think it's a critical problem. 
    Please help to speed up the processing， thanks very much!

Comment 13

[Blake Wu [:bwu][:blakewu]]

(In reply to [e-mail] from comment #11)
> Dear Black:
> When video app re-back to foreground, they should call
> EnsureAudioDecodeTaskQueued, and succeed to dispatch the DecodeAudio task,
> but most of time they do not dispatch the decodeaudio task successfully，
> cause the audio data do not decoded, followed the audioSeekComplete = 0,
> then can not fire the SeekCompleted task.
> 
> succeed:
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): Changed state from DECODING_METADATA to DECODING!
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 4
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 5
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): DecodeSeek: seekTime:110326000
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): mCurrentTimeBeforeSeek = 0
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): needToDecodeAudio = 0
> >> 01-12 23:43:27.363 I/lin.hui ==>( 1826): MediaDecoder::SeekingStarted
> >> 01-12 23:43:27.373 I/lin.hui ==>( 1826): OmxDecoder::Play
> >> 01-12 23:43:27.373 I/lin.hui ==>( 1826): OmxDecoder::Play
> >> 01-12 23:43:27.433 I/lin.hui ==>( 1826): needToDecodeAudio = 1
> >> 01-12 23:43:27.433 I/lin.hui ==>( 1826): MediaDecoderStateMachine::EnsureAudioDecodeTaskQueued
> >> 01-12 23:43:27.433 I/lin.hui ==>( 1826): dispatch DecodeAudio task starting
> >> 01-12 23:43:27.433 I/lin.hui ==>( 1826): dispatch DecodeAudio task succeed
> >> 01-12 23:43:27.433 I/lin.hui ==>( 1826): In DecodeAudio: mReader->RequestAudioData() mState:5
> 
> 
> failed:
> >> 01-12 23:32:23.273 I/lin.hui ==>( 1826): Changed state from DECODING_METADATA to DECODING!
> >> 01-12 23:32:23.273 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 4
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): RunStateMachine starting, mState = 5
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): DecodeSeek: seekTime:90344000
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): mCurrentTimeBeforeSeek = 0
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): needToDecodeAudio = 0
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): MediaDecoder::SeekingStarted
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): OmxDecoder::Play
> >> 01-12 23:32:23.283 I/lin.hui ==>( 1826): OmxDecoder::Play
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): needToDecodeAudio = 1
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): MediaDecoderStateMachine::EnsureAudioDecodeTaskQueued
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): IsVideoSeekComplete():video--> curTarVal=1 mVidDis=0 vqFin=0 vqSz=0
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): IsAudioSeekComplete():audio--> curTarVal=1 mAudDis=1 aqFin=0 aqSz=0
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): MediaDecoderStateMachine::EnsureAudioDecodeTaskQueued
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): CheckIfSeekComplete() audioSeekComplete=0 videoSeekComplete=0
> >> 01-12 23:32:23.343 I/lin.hui ==>( 1826): OmxDecoder::Play
> 
> I guess there may have something block the audio decoded.
Thanks for your help to narrow down this problem. I am checking it.

Comment 14

[Blake Wu [:bwu][:blakewu]]

(In reply to jinchao.wang from comment #12)
> (In reply to Blake Wu [:bwu][:blakewu] from comment #10)
> > I can repro this problem on my V2.1 Flame and start to investigate this bug.
> 
> Hi  Blake Wu:
>     This bug can reproduce easily in the steps of comment 5 on sprd7715ea
> and flame. We think it's a critical problem. 
>     Please help to speed up the processing， thanks very much!
Sure! I am checking this problem now.

Comment 15

[Blake Wu [:bwu][:blakewu]]

After some investigations, it looks like mVideoRequestPending and mAudioRequestPending are not reset after dormant state or backing to DecodeMetaData, so AudioDecodeTask and VideoDecodeTask will not be dispatched @[1][2]. 

I continue to check when to reset them in time. 

[1]http://mxr.mozilla.org/mozilla-b2g34_v2_1/source/content/media/MediaDecoderStateMachine.cpp#1728
[2]http://mxr.mozilla.org/mozilla-b2g34_v2_1/source/content/media/MediaDecoderStateMachine.cpp#1773

Comment 16

[[e-mail]]

Dear Blake:
This issue happened not just 720p video, in my own tests, all the video files can occurred yet.

Comment 17

[Blake Wu [:bwu][:blakewu]]

(In reply to [e-mail] from comment #16)
> Dear Blake:
> This issue happened not just 720p video, in my own tests, all the video
> files can occurred yet.
Yes. You are right. For high resolution videos, it should be more easily reproduced.

Comment 18

[Sotaro Ikeda [:sotaro]]

attachment 8547628 [details] [diff] [review] in Bug 1112410 seems to fix this. It got review+, but is not yet checked-in to b2g v2.1.
Can someone confirm it?

Comment 19

[Sotaro Ikeda [:sotaro]]

[Blocking Requested - why for this release]: Based on Comment 12 and Comment 10.

Comment 20

[Blake Wu [:bwu][:blakewu]]

(In reply to Sotaro Ikeda [:sotaro] from comment #18)
> attachment 8547628 [details] [diff] [review] in Bug 1112410 seems to fix
> this. It got review+, but is not yet checked-in to b2g v2.1.
> Can someone confirm it?
I think this patch should fix this bug as well. 
Lin, 
Could you have a try?

Comment 21

[[e-mail]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #20)
> (In reply to Sotaro Ikeda [:sotaro] from comment #18)
> > attachment 8547628 [details] [diff] [review] in Bug 1112410 seems to fix
> > this. It got review+, but is not yet checked-in to b2g v2.1.
> > Can someone confirm it?
> I think this patch should fix this bug as well. 
> Lin, 
> Could you have a try?

Dear Blake:

After applying that patch in v2.1, it's seems look good for me.

I will try do more test, and ensure that patch can fix this issue.

Thanks you very much!

Comment 22

[[e-mail]]

Dear Blake：

After some test，that patch can fix this issue suitable.

we think that patch should landed in v2.1 on mozillaorg.

Thanks!

Comment 23

[Blake Wu [:bwu][:blakewu]]

Great!
Thanks for Sotaro's patch :)

Comment 24

[[e-mail]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #23)
> Great!
> Thanks for Sotaro's patch :)

Does this patch already landed in 2.1? we think this fix should check-in 2.1.

Comment 25

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Sotaro, seems like the patch of Bug#1112410 does solve the problem, could you help to land it on 2.1? Then after that we will help to land on 2.1S as well

Thanks

Comment 26

[Blake Wu [:bwu][:blakewu]]

Un-assign myself since the solution to this bug is already in another bug (bug 1112410).

Comment 27

[Sotaro Ikeda [:sotaro]]

(In reply to Vance Chen [:vchen][[e-mail]] from comment #25)
> Hi Sotaro, seems like the patch of Bug#1112410 does solve the problem, could
> you help to land it on 2.1? Then after that we will help to land on 2.1S as
> well
> 
> Thanks

I just asked for approval-mozilla-b2g34 and approval-mozilla-b2g37 in bug 1112410.

Comment 28

[[e-mail]]

(In reply to Sotaro Ikeda [:sotaro] from comment #27)
> I just asked for approval-mozilla-b2g34 and approval-mozilla-b2g37 in bug
> 1112410.

The fix patch have already landed on v2.1, Thank you very much.