Closed Bug 1023564 Opened 10 years ago Closed 10 years ago

Intermittent test_seek.html | owl.mp3 seek test 2: Video currentTime should be around 1.645: 0.918803

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1039901
Tracking Flags:
Tracking Status
firefox31 --- disabled
firefox32 --- disabled
firefox33 --- disabled
firefox-esr24 --- unaffected
b2g-v2.0 --- disabled
b2g-v2.1 --- disabled

People

(Reporter: RyanVM, Assigned: rlin)

References

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled on B2G & Android]) 

Gah, "finished in 465488ms"

https://tbpl.mozilla.org/php/getParsedLog.php?id=41472637&tree=Fx-Team

b2g_emulator_vm fx-team opt test mochitest-3 on 2014-06-10 13:26:53 PDT for push c97f33da608d
slave: tst-linux64-spot-318

14:26:32     INFO -  1602 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [started owl.mp3-119-seek3.js] Length of array should match number of running tests
14:26:32     INFO -  1603 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek.html | owl.mp3 seek test 2: Video currentTime should be around 1.645: 0.918803
14:26:32     INFO -  SEEK-TEST: Finished owl.mp3 seek test 2 token: owl.mp3-118-seek2.js
14:26:34     INFO -  SEEK-TEST: Started owl.mp3 seek test 4
14:26:34     INFO -  SEEK-TEST: Finished owl.mp3 seek test 3 token: owl.mp3-119-seek3.js
14:26:36     INFO -  SEEK-TEST: Started owl.mp3 seek test 5
14:26:37     INFO -  SEEK-TEST: Finished owl.mp3 seek test 4 token: owl.mp3-120-seek4.js
14:26:39     INFO -  SEEK-TEST: Started owl.mp3 seek test 6
14:26:41     INFO -  SEEK-TEST: Finished owl.mp3 seek test 5 token: owl.mp3-121-seek5.js
14:26:43     INFO -  SEEK-TEST: Started owl.mp3 seek test 7
14:26:44     INFO -  SEEK-TEST: Finished owl.mp3 seek test 7 token: owl.mp3-123-seek7.js
14:26:44     INFO -  SEEK-TEST: Finished owl.mp3 seek test 6 token: owl.mp3-122-seek6.js
14:26:46     INFO -  SEEK-TEST: Started owl.mp3 seek test 8
14:26:46     INFO -  SEEK-TEST: Started owl.mp3 seek test 9
14:26:49     INFO -  SEEK-TEST: Finished owl.mp3 seek test 8 token: owl.mp3-124-seek8.js
14:26:50     INFO -  SEEK-TEST: Started owl.mp3 seek test 10
14:26:51     INFO -  SEEK-TEST: Finished owl.mp3 seek test 9 token: owl.mp3-125-seek9.js
14:26:53     INFO -  SEEK-TEST: Started owl.mp3 seek test 11
14:26:54     INFO -  SEEK-TEST: Finished owl.mp3 seek test 10 token: owl.mp3-126-seek10.js
14:26:55     INFO -  SEEK-TEST: Started owl.mp3 seek test 12
14:26:56     INFO -  SEEK-TEST: Finished owl.mp3 seek test 11 token: owl.mp3-127-seek11.js
14:26:58     INFO -  SEEK-TEST: Started owl.mp3 seek test 13
14:26:58     INFO -  SEEK-TEST: Finished owl.mp3 seek test 12 token: owl.mp3-128-seek12.js
14:27:00     INFO -  SEEK-TEST: Finished owl.mp3 seek test 13 token: owl.mp3-129-seek13.js
14:27:02     INFO -  1604 INFO TEST-INFO | MEMORY STAT vsize after test: 128364544
14:27:02     INFO -  1605 INFO TEST-INFO | MEMORY STAT residentFast after test: 52039680
14:27:02     INFO -  1606 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 28702800
14:27:02     INFO -  1607 INFO TEST-END | /tests/content/media/test/test_seek.html | finished in 465488ms
Assignee: nobody → rlin
http://hg.mozilla.org/mozilla-central/file/c4cf1181993e/content/media/omx/MediaOmxReader.cpp#l334
OmxDecoder::NotifyDataArrived is called only after mOmxDecoder is initialized in MediaOmxReader::InitOmxDecoder(). Therefore it is possible for |mMP3FrameParser| to parse data from the middle of the buffer in OmxDecoder::NotifyDataArrived(), and get a wrong MP3 duration.
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/e0d5eaee665b068949e80bd4f0732de4ffa3f21699d9e0e38d2383d7eba39ef07e55fffd1bff13164b2cf8c105c06d82962b6b5a5996ca4a4837433b83f48434

07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.066407 UTC - 64832[43d6c700]: Decoder=43d80640 Decoding Media Headers
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.066687 UTC - 64832[43d6c700]: Decoder=43d80640 DecodeMetadata first video frame start -1
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.066873 UTC - 64832[43d6c700]: Decoder=43d80640 DecodeMetadata first audio frame start 0
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.067079 UTC - 64832[43d6c700]: Decoder=43d80640 SetStartTime(0)
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.067247 UTC - 64832[43d6c700]: Decoder=43d80640 Set media start time to 0
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.067479 UTC - 64832[43d6c700]: Decoder=43d80640 Media goes from 0 to 78366 (duration 78366) transportSeekable=1, mediaSeekable=1
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.067788 UTC - 64832[43d6c700]: Decoder=43d80640 Changed state from DECODING_METADATA to DECODING
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.068053 UTC - 64832[43d6c700]: Decoder=43d80640 CheckIfDecodeComplete NOT completed
07-02 04:44:40.061   748  2403 I PRLog   : 2014-07-02 04:44:40.068680 UTC - 64832[43d6c700]: Decoder=43d80640 CheckIfDecodeComplete NOT completed
07-02 04:44:40.061   748  2395 I PRLog   : 2014-07-02 04:44:40.070730 UTC - 73824[44463580]: Decoder=43d80640 SetReaderIdle() audioQueue=0 videoQueue=0

From the log, we see the duration of the media file (owl.mp3) is 78366us. However, it should be 3.29s. So we are hitting comment 4 again which results in wrong mp3 duration.
http://hg.mozilla.org/mozilla-central/file/3a28d3bb4f55/content/media/MediaDecoderStateMachine.cpp#l1482
Since we can't seek to a position outside of [mStartTime, mEndTime], we end up at 78366us when trying to seek to 1.645s.
Disabled test_seek.html on all platforms for being a persistent source of intermittent test failures in multiple bugs:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a95eb3950035
Keywords: leave-open
Whiteboard: [test disabled]
(In reply to Ed Morley [:edmorley UTC+0] from comment #102)
> Disabled test_seek.html on all platforms for being a persistent source of
> intermittent test failures in multiple bugs:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/a95eb3950035

Randy, are you working on this at the moment?
Flags: needinfo?(rlin)
Re-enabled test_seek on platforms other than android and b2g. It's mostly orange on android and b2g.

https://hg.mozilla.org/integration/mozilla-inbound/rev/2937a989dbf8
This version seems good to figure out this problem.
https://tbpl.mozilla.org/?rev=3aea1fccf89c&tree=Try
As jwwang suggestion, this bug may cause by metadata parsing issue.
Flags: needinfo?(rlin)
Whiteboard: [test disabled] → [test disabled on B2G & Android]
No longer blocks: 1021681
Depends on: 1039901
Timing issue:
Found the NG pattern:
First, When OmxDecoder::TryLoad is called and read the starting data, also OmxDecoderNotifyDataArrivedRunnable
was started.

Then we got: 
*MediaDecoderStateMachine::NotifyDataArrived ->notify data again, the offset = 65536, call the 
*MediaOmxReader::NotifyDataArrived ->OmxDecoder::NotifyDataArrived  
* ^^^^Decoder haven't get the first frame, so the decoder try to parse it (it maybe the 2nd frame) through *MP3FrameParser::FindNumVBRFrames function and get the wrong duration.

After that, the OmxDecoderNotifyDataArrivedRunnable notify the first frame (offset = 0) and process it by OmxDecoder::NotifyDataArrived, it would go through the MP3FrameParser::Parse and ignore by 
https://mxr.mozilla.org/mozilla-central/source/content/media/MP3FrameParser.cpp#449
Blocks: 1056629
No longer blocks: 1056629
Bug 1039901 has fixed this issue, set duplicate.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → DUPLICATE
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.