Closed Bug 1023564 Opened 11 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.