Closed Bug 1671931 Opened 4 years ago Closed 4 years ago

ThreadSanitizer: data race on VideoFrameContainer::mFrameID

Categories

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

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

Tracking

()

Status:
RESOLVED FIXED
Milestone:
84 Branch
Tracking Flags:
Tracking Status
firefox84 --- fixed

People

(Reporter: bwc, Assigned: pehrsons)

References

(Blocks 1 open bug)

Details

Attachments

(3 files)

tsan output when assertion is added
9.16 KB, text/plain
Details
Bug 1671931 - Let VideoOutput roll its own FrameID generator. r?bwc!
47 bytes, text/x-phabricator-request
Details | Review
Bug 1671931 - Remove some `using` keywords and set up typedefs in VideoOutput.h. r?bwc!
47 bytes, text/x-phabricator-request
Details | Review

It looks like this is being called by both the MediaTrackGraph thread, and the PBackground thread handling PCamerasChild:

https://searchfox.org/mozilla-central/rev/819be4899a92213abf121b449779ced662f2ce13/dom/media/VideoFrameContainer.h#80

Making the counter atomic would probably fix this race, although we should look into whether there are more serious races between these two threads.

[task 2020-10-16T21:38:47.611Z] 21:38:47 INFO - GECKO(2999) | WARNING: ThreadSanitizer: data race (pid=3139)
[task 2020-10-16T21:38:47.612Z] 21:38:47 INFO - GECKO(2999) | Write of size 4 at 0x7b240010ed50 by thread T25 (mutexes: write M333964871547666752, write M428258971567397680, write M577722132659298432, write M10831426486119576):
[task 2020-10-16T21:38:47.612Z] 21:38:47 INFO - GECKO(2999) | #0 NewFrameID /builds/worker/checkouts/gecko/dom/media/VideoFrameContainer.h:80:49 (libxul.so+0x3a1cebe)
[task 2020-10-16T21:38:47.612Z] 21:38:47 INFO - GECKO(2999) | #1 mozilla::VideoOutput::NotifyRealtimeTrackData(mozilla::MediaTrackGraph*, long, mozilla::MediaSegment const&) /builds/worker/checkouts/gecko/dom/media/VideoOutput.h:146:48 (libxul.so+0x3a1cebe)
[task 2020-10-16T21:38:47.613Z] 21:38:47 INFO - GECKO(2999) | #2 mozilla::DirectMediaTrackListener::NotifyRealtimeTrackDataAndApplyTrackDisabling(mozilla::MediaTrackGraph*, long, mozilla::MediaSegment&) /builds/worker/checkouts/gecko/dom/media/MediaTrackListener.cpp:58:3 (libxul.so+0x3c80437)
[task 2020-10-16T21:38:47.613Z] 21:38:47 INFO - GECKO(2999) | #3 NotifyDirectConsumers /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:2724:8 (libxul.so+0x3c801ba)
[task 2020-10-16T21:38:47.614Z] 21:38:47 INFO - GECKO(2999) | #4 mozilla::SourceMediaTrack::AppendData(mozilla::MediaSegment*, mozilla::MediaSegment*) /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:2693:3 (libxul.so+0x3c801ba)
[task 2020-10-16T21:38:47.614Z] 21:38:47 INFO - GECKO(2999) | #5 mozilla::MediaEngineRemoteVideoSource::DeliverFrame(unsigned char*, mozilla::camera::VideoFrameProperties const&) /builds/worker/checkouts/gecko/dom/media/webrtc/MediaEngineRemoteVideoSource.cpp:630:13 (libxul.so+0x400a4fe)
[task 2020-10-16T21:38:47.615Z] 21:38:47 INFO - GECKO(2999) | #6 non-virtual thunk to mozilla::MediaEngineRemoteVideoSource::DeliverFrame(unsigned char*, mozilla::camera::VideoFrameProperties const&) /builds/worker/checkouts/gecko/dom/media/webrtc/MediaEngineRemoteVideoSource.cpp (libxul.so+0x400a5e9)
[task 2020-10-16T21:38:47.616Z] 21:38:47 INFO - GECKO(2999) | #7 mozilla::camera::CamerasChild::RecvDeliverFrame(mozilla::camera::CaptureEngine const&, int const&, mozilla::ipc::Shmem&&, mozilla::camera::VideoFrameProperties const&) /builds/worker/checkouts/gecko/dom/media/systemservices/CamerasChild.cpp:515:33 (libxul.so+0x3f3ac70)
[task 2020-10-16T21:38:47.617Z] 21:38:47 INFO - GECKO(2999) | #8 mozilla::camera::PCamerasChild::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PCamerasChild.cpp:470:28 (libxul.so+0x1981b6e)
[task 2020-10-16T21:38:47.617Z] 21:38:47 INFO - GECKO(2999) | #9 mozilla::ipc::PBackgroundChild::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PBackgroundChild.cpp:6249:32 (libxul.so+0x168e993)
[task 2020-10-16T21:38:47.618Z] 21:38:47 INFO - GECKO(2999) | #10 mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2150:25 (libxul.so+0x143eceb)
[task 2020-10-16T21:38:47.623Z] 21:38:47 INFO - GECKO(2999) | #11 mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2074:9 (libxul.so+0x143d15c)
[task 2020-10-16T21:38:47.624Z] 21:38:47 INFO - GECKO(2999) | #12 mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1922:3 (libxul.so+0x143dd3a)
[task 2020-10-16T21:38:47.624Z] 21:38:47 INFO - GECKO(2999) | #13 mozilla::ipc::MessageChannel::MessageTask::Run() /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1953:13 (libxul.so+0x143e281)
[task 2020-10-16T21:38:47.624Z] 21:38:47 INFO - GECKO(2999) | #14 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1197:14 (libxul.so+0xb5fc7d)
[task 2020-10-16T21:38:47.624Z] 21:38:47 INFO - GECKO(2999) | #15 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:513:10 (libxul.so+0xb64fd2)
[task 2020-10-16T21:38:47.625Z] 21:38:47 INFO - GECKO(2999) | #16 mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:332:5 (libxul.so+0x1443158)
[task 2020-10-16T21:38:47.625Z] 21:38:47 INFO - GECKO(2999) | #17 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:334:10 (libxul.so+0x13d33fc)
[task 2020-10-16T21:38:47.625Z] 21:38:47 INFO - GECKO(2999) | #18 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:327:3 (libxul.so+0x13d33fc)
[task 2020-10-16T21:38:47.625Z] 21:38:47 INFO - GECKO(2999) | #19 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:309:3 (libxul.so+0x13d33fc)
[task 2020-10-16T21:38:47.626Z] 21:38:47 INFO - GECKO(2999) | #20 nsThread::ThreadFunc(void*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:442:10 (libxul.so+0xb5c101)
[task 2020-10-16T21:38:47.630Z] 21:38:47 INFO - GECKO(2999) | #21 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x4500b)
[task 2020-10-16T21:38:47.631Z] 21:38:47 INFO - GECKO(2999) | Previous write of size 4 at 0x7b240010ed50 by thread T65 (mutexes: write M572092633124663624, write M9705560937637016):
[task 2020-10-16T21:38:47.631Z] 21:38:47 INFO - GECKO(2999) | #0 NewFrameID /builds/worker/checkouts/gecko/dom/media/VideoFrameContainer.h:80:49 (libxul.so+0x3a1bf72)
[task 2020-10-16T21:38:47.631Z] 21:38:47 INFO - GECKO(2999) | #1 mozilla::VideoOutput::NotifyEnabledStateChanged(mozilla::MediaTrackGraph*, bool) /builds/worker/checkouts/gecko/dom/media/VideoOutput.h:200:51 (libxul.so+0x3a1bf72)
[task 2020-10-16T21:38:47.631Z] 21:38:47 INFO - GECKO(2999) | #2 mozilla::MediaTrack::NotifyIfDisabledModeChangedFrom(mozilla::DisabledTrackMode) /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:2408:15 (libxul.so+0x3c7ef2d)
[task 2020-10-16T21:38:47.632Z] 21:38:47 INFO - GECKO(2999) | #3 mozilla::MediaTrack::SetDisabledTrackModeImpl(mozilla::DisabledTrackMode) /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:2309:3 (libxul.so+0x3c7ee24)
[task 2020-10-16T21:38:47.632Z] 21:38:47 INFO - GECKO(2999) | #4 mozilla::ForwardedInputTrack::SetDisabledTrackModeImpl(mozilla::DisabledTrackMode) /builds/worker/checkouts/gecko/dom/media/ForwardedInputTrack.cpp:215:15 (libxul.so+0x3aeace6)
[task 2020-10-16T21:38:47.634Z] 21:38:47 INFO - GECKO(2999) | #5 mozilla::MediaTrack::SetDisabledTrackMode(mozilla::DisabledTrackMode)::Message::Run() /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:2317:35 (libxul.so+0x3c9bd7f)
[task 2020-10-16T21:38:47.634Z] 21:38:47 INFO - GECKO(2999) | #6 mozilla::MediaTrackGraphImpl::RunMessagesInQueue() /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:1151:20 (libxul.so+0x3c78628)
[task 2020-10-16T21:38:47.634Z] 21:38:47 INFO - GECKO(2999) | #7 mozilla::MediaTrackGraphImpl::OneIterationImpl(long, long, mozilla::AudioMixer*) /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:1394:3 (libxul.so+0x3c7a60e)
[task 2020-10-16T21:38:47.634Z] 21:38:47 INFO - GECKO(2999) | #8 mozilla::GraphRunner::Run() /builds/worker/checkouts/gecko/dom/media/GraphRunner.cpp:116:32 (libxul.so+0x3b0c5e1)
[task 2020-10-16T21:38:47.640Z] 21:38:47 INFO - GECKO(2999) | #9 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1197:14 (libxul.so+0xb5fc7d)
[task 2020-10-16T21:38:47.640Z] 21:38:47 INFO - GECKO(2999) | #10 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:513:10 (libxul.so+0xb64fd2)
[task 2020-10-16T21:38:47.640Z] 21:38:47 INFO - GECKO(2999) | #11 mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:332:5 (libxul.so+0x1443158)
[task 2020-10-16T21:38:47.640Z] 21:38:47 INFO - GECKO(2999) | #12 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:334:10 (libxul.so+0x13d33fc)
[task 2020-10-16T21:38:47.644Z] 21:38:47 INFO - GECKO(2999) | #13 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:327:3 (libxul.so+0x13d33fc)
[task 2020-10-16T21:38:47.644Z] 21:38:47 INFO - GECKO(2999) | #14 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:309:3 (libxul.so+0x13d33fc)
[task 2020-10-16T21:38:47.644Z] 21:38:47 INFO - GECKO(2999) | #15 nsThread::ThreadFunc(void*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:442:10 (libxul.so+0xb5c101)
[task 2020-10-16T21:38:47.644Z] 21:38:47 INFO - GECKO(2999) | #16 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x4500b)

Blocks: tsan, mochitest_media_tsan

Both stacks in comment 1 are accessing NewFrameID() behind VideoOutput::mMutex: https://searchfox.org/mozilla-central/rev/819be4899a92213abf121b449779ced662f2ce13/dom/media/VideoOutput.h#137,186

Are there two VideoOutputs attached to the same VideoFrameContainer? That would be a bug.

Could be. Let me try adding an assertion...

Pondering a bit about this I suspect it could be the main VideoOutput, and the first-frame-VideoOutput now being active at the same time.

Doh. I'll see what I can do.

FWIW the worst case scenario here should be that nothing happens since these two VideoOutputs have different producer IDs, and generating that is thread-safe.

Assignee: nobody → apehrson
Severity: -- → S4
Status: NEW → ASSIGNED
Priority: -- → P3

Hmm, P2 based on bug 1648192.

Priority: P3 → P2
I added an assertion to try to catch double-attachment, and that code was racy too; it looks like attach/detach can happen on different threads:

I could believe that the dtor is called off-main, but RemoveVideoOutput() should be on main thread only.

There is a case where two VideoOutputs are feeding the same VideoFrameContainer
with data: VideoStreamTrack::AddVideoOutput(VideoFrameContainer) and
VideoStreamTrack::AddVideoOutput(FirstFrameVideoOutput) in HTMLMediaElement.
This is racy since they both call VideoFrameContainer::NewFrameID().

These VideoOutputs use different ProducerIDs however, so it makes sense for them
to also use separate FrameID generators.

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/d904a6ca71de
Let VideoOutput roll its own FrameID generator. r=bwc
https://hg.mozilla.org/integration/autoland/rev/1777751d3eba
Remove some `using` keywords and set up typedefs in VideoOutput.h. r=bwc

https://hg.mozilla.org/mozilla-central/rev/d904a6ca71de
https://hg.mozilla.org/mozilla-central/rev/1777751d3eba

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox84: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 84 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: