Open Bug 1593209 Opened 5 years ago Updated 2 years ago

MacOS 10.14 machines running WPT in automation are not able to drive a SystemClockDriver

Categories

(Core :: Audio/Video: MediaStreamGraph, defect, P3)

Product:
Core
Component:
Audio/Video: MediaStreamGraph
Type:
defect

Tracking

()

People

(Reporter: pehrsons, Unassigned)

References

Details

See this log snippet from this try run:

Main Thread: D/MediaTrackGraph Starting up MediaTrackGraph 0x11aacbc00 for window 0x11b19d020
Main Thread: D/MediaTrackGraph 0x11aacbc00: Running stable state callback. Current state: LIFECYCLE_THREAD_NOT_STARTED
Main Thread: D/MediaTrackGraph 0x11aacbc00: Starting a graph with a SystemClockDriver
Main Thread: D/MediaTrackGraph Starting thread for a SystemClockDriver 0x11aacbc00
MediaTrackGrph: D/MediaTrackGraph Starting a new system driver for graph 0x11aacbc00
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Updating current time to 0.004218 (real 0.004236, StateComputedTime() 0.000000)
MediaTrackGrph: W/MediaTrackGraph 0x11aacbc00: Global underrun detected
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Time did not advance
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: interval[0; 0] state[0; 1408]
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Adding media track 0x11b152710, count 1
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Adding media track 0x11bbfd300, count 2
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Adding MediaInputPort 0x11bba7250 (from 0x11b152710 to 0x11bbfd300)
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: SourceMediaTrack 0x11b152710 advancing end from 0 to 1408
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152710 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11bbfd300 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Waiting for next iteration; at 0.004325, timeout=0.010000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Resuming after timeout
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Updating current time to 0.066077 (real 0.070330, StateComputedTime() 0.031927)
MediaTrackGrph: W/MediaTrackGraph 0x11aacbc00: Global underrun detected
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: interval[0; 1408] state[1408; 2816]
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Adding media track 0x11b152970, count 3
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Adding direct track listener 0x11bbd74c0 to source track 0x11b152710
MediaTrackGrph: D/MediaTrackGraph 0x11aacbc00: Added direct track listener 0x11bbd74c0
MediaTrackGrph: I/MediaTrackGraph 0x11aacbc00: Notifying direct listener 0x11bbd74c0 of 0 video frames and duration 0
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: SourceMediaTrack 0x11b152710 advancing end from 1408 to 2816
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152710 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11bbfd300 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152970 bufferStartTime=0.063855 blockedTime=0.031927
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Waiting for next iteration; at 0.070463, timeout=0.010000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Resuming after timeout
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Updating current time to 0.118776 (real 0.157183, StateComputedTime() 0.063855)
MediaTrackGrph: W/MediaTrackGraph 0x11aacbc00: Global underrun detected
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: interval[1408; 2816] state[2816; 4224]
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: SourceMediaTrack 0x11b152710 advancing end from 2816 to 4224
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152710 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11bbfd300 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152970 bufferStartTime=0.095782 blockedTime=0.031927
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Waiting for next iteration; at 0.157331, timeout=0.010000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Resuming after timeout
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Updating current time to 0.153084 (real 0.246430, StateComputedTime() 0.095782)
MediaTrackGrph: W/MediaTrackGraph 0x11aacbc00: Global underrun detected
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: interval[2816; 4224] state[4224; 5632]
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: SourceMediaTrack 0x11b152710 advancing end from 4224 to 5632
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152710 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11bbfd300 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152970 bufferStartTime=0.127710 blockedTime=0.031927
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Waiting for next iteration; at 0.246485, timeout=0.010000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Resuming after timeout
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Updating current time to 0.165714 (real 0.316377, StateComputedTime() 0.127710)
MediaTrackGrph: W/MediaTrackGraph 0x11aacbc00: Global underrun detected
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: interval[4224; 5632] state[5632; 7040]
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: SourceMediaTrack 0x11b152710 advancing end from 5632 to 7040
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152710 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11bbfd300 bufferStartTime=0.000000 blockedTime=0.000000
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: MediaTrack 0x11b152970 bufferStartTime=0.159637 blockedTime=0.031927
MediaTrackGrph: V/MediaTrackGraph 0x11aacbc00: Waiting for next iteration; at 0.316450, timeout=0.010000

Lots of global underruns.

A typical Monitor::Wait(10ms) waits for considerably longer (here 55ms):

[task 2019-10-31T18:10:10.178Z] V/MediaTrackGraph 0x11aacbc00: Waiting for next iteration; at 0.246485, timeout=0.010000
[task 2019-10-31T18:10:10.233Z] V/MediaTrackGraph 0x11aacbc00: Resuming after timeout

The last currentTime update for this test reads:

V/MediaTrackGraph 0x11aacbc00: Updating current time to 2.569932 (real 6.256306, StateComputedTime() 2.513560)

Meaning the graph only processed 2.57s worth of track data in 6.26s wall-clock time. It's not even able to keep half the speed of what the test needs.

FWIW timeoutMS in SystemClockDriver::WaitInterval() has ms precision, and so all "timeout=0.010000" messages indicate that each processing iteration took less than one millisecond.

Based on "at" and "real", the actual wait times are 66.0, 86.7, 89.1, 69.9 ms.

Severity: normal normal → S3 S3
You need to log in before you can comment on or make changes to this bug.