Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Apply double check pattern to avoid race condition in LoggingService #11284

Draft
wants to merge 2 commits into
base: main
Choose a base branch
from
Draft
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
57 changes: 41 additions & 16 deletions src/Build/BackEnd/Components/Logging/LoggingService.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
// Licensed to the .NET Foundation under one or more agreements.
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System;
Expand All @@ -10,12 +10,12 @@
using System.Threading;
using Microsoft.Build.BackEnd.Components.RequestBuilder;
using Microsoft.Build.Evaluation;
using Microsoft.Build.Experimental.BuildCheck;
using Microsoft.Build.Experimental.BuildCheck.Infrastructure;
using Microsoft.Build.Framework;
using Microsoft.Build.Shared;
using InternalLoggerException = Microsoft.Build.Exceptions.InternalLoggerException;
using LoggerDescription = Microsoft.Build.Logging.LoggerDescription;
using Microsoft.Build.Experimental.BuildCheck;

#nullable disable

Expand Down Expand Up @@ -248,15 +248,32 @@ internal partial class LoggingService : ILoggingService, INodePacketHandler
/// Event set when message is consumed from queue.
/// </summary>
private AutoResetEvent _dequeueEvent;

/// <summary>
/// Local copy of dequeue event to avoid race condition on shutdown operation.
/// </summary>
private AutoResetEvent _dequeueEventDoubleCheckCopy;

/// <summary>
/// Event set when queue become empty.
/// Event set when queue become empty.
/// </summary>
private ManualResetEvent _emptyQueueEvent;

/// <summary>
/// Local copy of empty queue event to avoid race condition on shutdown operation.
/// </summary>
private ManualResetEvent _emptyQueueEventDoubleCheckCopy;

/// <summary>
/// Even set when message is added into queue.
/// Event set when message is added into queue.
/// </summary>
private AutoResetEvent _enqueueEvent;

/// <summary>
/// Local copy of enqueue event to avoid race condition on shutdown operation.
/// </summary>
private AutoResetEvent _enqueueEventDoubleCheckCopy;

/// <summary>
/// CTS for stopping logging event processing.
/// </summary>
Expand Down Expand Up @@ -1302,11 +1319,11 @@ protected internal virtual void ProcessLoggingEvent(object buildEvent)
while (_eventQueue.Count >= _queueCapacity)
{
// Block and wait for dequeue event.
_dequeueEvent.WaitOne();
_dequeueEventDoubleCheckCopy.WaitOne();
}

_eventQueue.Enqueue(buildEvent);
_enqueueEvent.Set();
_enqueueEventDoubleCheckCopy.Set();
}
else
{
Expand All @@ -1327,12 +1344,13 @@ public void WaitForLoggingToProcessEvents()
{
while (_eventQueue?.IsEmpty == false)
{
_emptyQueueEvent?.WaitOne();
_emptyQueueEventDoubleCheckCopy?.WaitOne();
}

// To avoid race condition when last message has been removed from queue but
// not yet fully processed (handled by loggers), we need to make sure _emptyQueueEvent
// is set as it is guaranteed to be in set state no sooner than after event has been processed.
_emptyQueueEvent?.WaitOne();
_emptyQueueEventDoubleCheckCopy?.WaitOne();
}

/// <summary>
Expand Down Expand Up @@ -1385,11 +1403,17 @@ private static WarningsConfigKey GetWarningsConfigKey(BuildEventArgs buildEventA
private void StartLoggingEventProcessing()
{
_eventQueue = new ConcurrentQueue<object>();

_dequeueEvent = new AutoResetEvent(false);
_dequeueEventDoubleCheckCopy = _dequeueEvent;

_emptyQueueEvent = new ManualResetEvent(false);
_emptyQueueEventDoubleCheckCopy = _emptyQueueEvent;

_enqueueEvent = new AutoResetEvent(false);
_loggingEventProcessingCancellation = new CancellationTokenSource();
_enqueueEventDoubleCheckCopy = _enqueueEvent;

_loggingEventProcessingCancellation = new CancellationTokenSource();
_loggingEventProcessingThread = new Thread(LoggingEventProc);
_loggingEventProcessingThread.Name = $"MSBuild LoggingService events queue pump: {this.GetHashCode()}";
_loggingEventProcessingThread.IsBackground = true;
Expand All @@ -1398,34 +1422,32 @@ private void StartLoggingEventProcessing()
void LoggingEventProc()
{
var completeAdding = _loggingEventProcessingCancellation.Token;
WaitHandle[] waitHandlesForNextEvent = { completeAdding.WaitHandle, _enqueueEvent };
WaitHandle[] waitHandlesForNextEvent = { completeAdding.WaitHandle, _enqueueEventDoubleCheckCopy };

do
{
if (_eventQueue.TryDequeue(out object ev))
{
LoggingEventProcessor(ev);
_dequeueEvent.Set();
_dequeueEventDoubleCheckCopy?.Set();
}
else
{
_emptyQueueEvent.Set();
_emptyQueueEventDoubleCheckCopy?.Set();

// Wait for next event, or finish.
if (!completeAdding.IsCancellationRequested && _eventQueue.IsEmpty)
{
WaitHandle.WaitAny(waitHandlesForNextEvent);
}

_emptyQueueEvent.Reset();
_emptyQueueEventDoubleCheckCopy?.Reset();
}
} while (!_eventQueue.IsEmpty || !completeAdding.IsCancellationRequested);

_emptyQueueEvent.Set();
_emptyQueueEventDoubleCheckCopy?.Set();
}
}


/// <summary>
/// Clean resources used for logging event processing queue.
/// </summary>
Expand All @@ -1439,8 +1461,11 @@ private void CleanLoggingEventProcessing()

_eventQueue = null;
_dequeueEvent = null;
_dequeueEventDoubleCheckCopy = null;
_enqueueEvent = null;
_enqueueEventDoubleCheckCopy = null;
_emptyQueueEvent = null;
_emptyQueueEventDoubleCheckCopy = null;
_loggingEventProcessingCancellation = null;
_loggingEventProcessingThread = null;
}
Expand Down