Skip to content

Commit

Permalink
LoggingService log contention (#7492)
Browse files Browse the repository at this point in the history
Fixes #7364

Context
LoggingService.LogComment causes large amounts of contention between unrelated evaluation threads.
image

Changes Made
Reducing lock statements
using Interlock.Add as oppose to lock { n+=x; }
replace Dictionary with ConcurrentDictionary and remove related locks
review locks and remove unnecessary
Replacing DataFlow by ConcurrentQueue for event processing
Fixing unit tests
Testing
local run unit testst
micro benchmark comparing DataFlow by ConcurrentQueue
exp insertion - currently failing on infrastructure - will update
Compiled Boost.Hana as described in OOM when generating binlog for boost.hana #3577 - no OOM exception
Notes
It has surprisingly good perf results. Maybe because I tested it on 24 core machine where lock contention in LoggingService could be a bigger issue.

command	Duration	RAM
msbuild /m /bl OrchardCore.sln	-25%	-4%
msbuild /m OrchardCore.sln	-13%	-3%
Microbenchmark comparing DataFlow vs ConcurrentQueue processing 1E6 messages showed ~2 seconds saving (-85%) and about ~250MB allocations less (-92%). I was also considering to use BlockingCollection but for this we do not have support in net3.5 and also I have seen weird huge perf degradation for my use case in net472.

Method	Mean	Allocated
DataFlow	2,558,860.6 us	297,286,352 B
CocurrentQueue	371,877.9 us	26,304,552 B
  • Loading branch information
rokonec committed Apr 26, 2022
1 parent cff0b1f commit fe30002
Show file tree
Hide file tree
Showing 7 changed files with 536 additions and 592 deletions.
3 changes: 2 additions & 1 deletion src/Build.UnitTests/BackEnd/LoggingServiceFactory_Tests.cs
Expand Up @@ -34,6 +34,7 @@ public void TestCreateAsynchronousLogger()
LoggingServiceFactory factory = new LoggingServiceFactory(LoggerMode.Asynchronous, 1);
LoggingService loggingService = (LoggingService)factory.CreateInstance(BuildComponentType.LoggingService);
Assert.Equal(LoggerMode.Asynchronous, loggingService.LoggingMode); // "Expected to create an Asynchronous LoggingService"
loggingService.ShutdownComponent();
}
}
}
}
Expand Up @@ -1099,6 +1099,7 @@ public void TestBuildFinishedWaitForEvents()
{
ProcessBuildEventHelper service = (ProcessBuildEventHelper)ProcessBuildEventHelper.CreateLoggingService(LoggerMode.Asynchronous, 1);
service.LogBuildFinished(true);
service.ShutdownComponent();
}

#endregion
Expand Down Expand Up @@ -1898,7 +1899,7 @@ public static IBuildComponent CreateLoggingService(LoggerMode mode, int nodeId,
/// Override the method to log which event was processed so it can be verified in a test
/// </summary>
/// <param name="buildEvent">Build event which was asked to be processed</param>
internal override void ProcessLoggingEvent(object buildEvent, bool allowThrottling = false)
internal override void ProcessLoggingEvent(object buildEvent)
{
if (buildEvent is BuildEventArgs buildEventArgs)
{
Expand Down
2 changes: 1 addition & 1 deletion src/Build/BackEnd/BuildManager/BuildManager.cs
Expand Up @@ -1662,7 +1662,7 @@ private void WaitForAllLoggingServiceEventsToBeProcessed()
// this has to be called out of the lock (_syncLock)
// because processing events can callback to 'this' instance and cause deadlock
Debug.Assert(!Monitor.IsEntered(_syncLock));
((LoggingService) ((IBuildComponentHost) this).LoggingService).WaitForThreadToProcessEvents();
((LoggingService) ((IBuildComponentHost) this).LoggingService).WaitForLoggingToProcessEvents();
}

/// <summary>
Expand Down

0 comments on commit fe30002

Please sign in to comment.