From 6661d3c2eea31a697c39feb6d03a1a03f1995a14 Mon Sep 17 00:00:00 2001 From: Jiu Date: Wed, 1 Nov 2023 23:53:18 +0100 Subject: [PATCH] fix: stuff --- Rin.BuildEngine.Common/Builder.cs | 137 ++++++++------- Rin.BuildEngine.Common/CommandIOMonitor.cs | 160 ++++++++++++++++++ Rin.BuildEngine.Common/TimeInterval.cs | 46 +++++ .../Storage/BundleOdbBackend.cs | 2 +- Rin.Core/Extensions/ArrayExtensions.cs | 29 ++++ 5 files changed, 302 insertions(+), 72 deletions(-) create mode 100644 Rin.BuildEngine.Common/CommandIOMonitor.cs create mode 100644 Rin.BuildEngine.Common/TimeInterval.cs create mode 100644 Rin.Core/Extensions/ArrayExtensions.cs diff --git a/Rin.BuildEngine.Common/Builder.cs b/Rin.BuildEngine.Common/Builder.cs index ac48708..e8512e2 100644 --- a/Rin.BuildEngine.Common/Builder.cs +++ b/Rin.BuildEngine.Common/Builder.cs @@ -12,20 +12,45 @@ namespace Rin.BuildEngine.Common; public class Builder : IDisposable { public const int ExpectedVersion = 4; + + public const string MonitorPipeName = "Rin/BuildEngine/Monitor"; public static readonly string DoNotCompressTag = "DoNotCompress"; public static readonly string DoNotPackTag = "DoNotPack"; + public readonly ISet DisableCompressionIds = new HashSet(); + + /// - /// The full path of the index file from the build directory. + /// The path on the disk where to perform the build /// - string IndexFileFullPath => - indexName != null - ? VirtualFileSystem.ApplicationDatabasePath + VirtualFileSystem.DirectorySeparatorChar + indexName - : null; + readonly string buildPath; - public const string MonitorPipeName = "Stride/BuildEngine/Monitor"; + /// + /// The name on the disk of the index file name. + /// + readonly string indexName; - public readonly ISet DisableCompressionIds = new HashSet(); + readonly CommandIOMonitor ioMonitor; + readonly DateTime startTime; + readonly StepCounter stepCounter = new(); + + /// + /// Cancellation token source used for cancellation. + /// + CancellationTokenSource cancellationTokenSource; + + /// + /// A map containing results of each commands, indexed by command hashes. When the builder is running, this map if + /// filled with the result of the commands of the current execution. + /// + ObjectDatabase resultMap; + + /// + /// The build mode of the current run execution + /// + Mode runMode; + + Scheduler scheduler; /// /// Gets the in which built objects are written. @@ -74,59 +99,12 @@ public class Builder : IDisposable { public CommandBuildStep.TryExecuteRemoteDelegate TryExecuteRemote { get; set; } /// - /// Indicate which mode to use with this builder - /// - public enum Mode { - /// - /// Build the script - /// - Build, - - /// - /// Clean the command cache used to determine wheither a command has already been triggered. - /// - Clean, - - /// - /// Clean the command cache and delete every output objects - /// - CleanAndDelete - } - - - /// - /// The path on the disk where to perform the build - /// - readonly string buildPath; - - /// - /// The name on the disk of the index file name. - /// - readonly string indexName; - - readonly CommandIOMonitor ioMonitor; - - readonly DateTime startTime; - - readonly StepCounter stepCounter = new StepCounter(); - - /// - /// Cancellation token source used for cancellation. - /// - CancellationTokenSource cancellationTokenSource; - - /// - /// A map containing results of each commands, indexed by command hashes. When the builder is running, this map if - /// filled with the result of the commands of the current execution. - /// - ObjectDatabase resultMap; - - /// - /// The build mode of the current run execution + /// The full path of the index file from the build directory. /// - Mode runMode; - - Scheduler scheduler; + string IndexFileFullPath => + indexName != null + ? VirtualFileSystem.ApplicationDatabasePath + VirtualFileSystem.DirectorySeparatorChar + indexName + : null; public Builder(ILogger logger, string buildPath, string indexName) { @@ -136,7 +114,7 @@ public Builder(ILogger logger, string buildPath, string indexName) { Logger = logger; this.buildPath = buildPath ?? throw new ArgumentNullException(nameof(buildPath)); Root = new(); - ioMonitor = new CommandIOMonitor(Logger); + ioMonitor = new(Logger); ThreadCount = Environment.ProcessorCount; BuilderId = Guid.NewGuid(); InitialVariables = new Dictionary(); @@ -188,7 +166,6 @@ public BuildResultCode Run(Mode mode, bool writeIndexFile = true) { OpenObjectDatabase(buildPath, indexName); PreRun(); - runMode = mode; if (IsRunning) { @@ -205,9 +182,7 @@ public BuildResultCode Run(Mode mode, bool writeIndexFile = true) { var inputHashes = FileVersionTracker.GetDefault(); { var builderContext = new BuilderContext(inputHashes, TryExecuteRemote); - resultMap = ObjectDatabase; - scheduler = new(); // Schedule the build @@ -240,15 +215,15 @@ public BuildResultCode Run(Mode mode, bool writeIndexFile = true) { } else if (stepCounter.Get(ResultStatus.Failed) > 0 || stepCounter.Get(ResultStatus.NotTriggeredPrerequisiteFailed) > 0) { Logger.Error( - $"Build finished in {stepCounter.Total} steps. Command results: {stepCounter.Get(ResultStatus.Successful)} succeeded, {stepCounter.Get(ResultStatus.NotTriggeredWasSuccessful)} up-to-date, {stepCounter.Get(ResultStatus.Failed)} failed, {stepCounter.Get(ResultStatus.NotTriggeredPrerequisiteFailed)} not triggered due to previous failure." + $"Build finished in {stepCounter.Total} steps. Command results: {stepCounter.Get(ResultStatus.Successful)} succeeded, {stepCounter.Get(ResultStatus.NotTriggeredWasSuccessful)} up-to-date, {stepCounter.Get(ResultStatus.Failed)} failed, {stepCounter.Get(ResultStatus.NotTriggeredPrerequisiteFailed)} not triggered due to previous failure" ); Logger.Error("Build failed."); result = BuildResultCode.BuildError; } else { - Logger.Info( - $"Build finished in {stepCounter.Total} steps. Command results: {stepCounter.Get(ResultStatus.Successful)} succeeded, {stepCounter.Get(ResultStatus.NotTriggeredWasSuccessful)} up-to-date, {stepCounter.Get(ResultStatus.Failed)} failed, {stepCounter.Get(ResultStatus.NotTriggeredPrerequisiteFailed)} not triggered due to previous failure." + Logger.Information( + $"Build finished in {stepCounter.Total} steps. Command results: {stepCounter.Get(ResultStatus.Successful)} succeeded, {stepCounter.Get(ResultStatus.NotTriggeredWasSuccessful)} up-to-date, {stepCounter.Get(ResultStatus.Failed)} failed, {stepCounter.Get(ResultStatus.NotTriggeredPrerequisiteFailed)} not triggered due to previous failure" ); - Logger.Info("Build is successful."); + Logger.Information("Build is successful"); result = BuildResultCode.Successful; } } else { @@ -267,14 +242,14 @@ public BuildResultCode Run(Mode mode, bool writeIndexFile = true) { } if (cancellationTokenSource.IsCancellationRequested) { - Logger.Error(modeName + " has been cancelled."); + Logger.Error(modeName + " has been cancelled"); result = BuildResultCode.Cancelled; } else if (stepCounter.Get(ResultStatus.Failed) > 0 || stepCounter.Get(ResultStatus.NotTriggeredPrerequisiteFailed) > 0) { - Logger.Error(modeName + " has failed."); + Logger.Error(modeName + " has failed"); result = BuildResultCode.BuildError; } else { - Logger.Error(modeName + " has been successfully completed."); + Logger.Error(modeName + " has been successfully completed"); result = BuildResultCode.Successful; } } @@ -407,7 +382,7 @@ void ComputeDependencyGraph(Dictionary /// The root BuildStep void GenerateDependencies(BuildStep rootStep) { - // TODO: Support proper incremental dependecies + // TODO: Support proper incremental dependencies if (rootStep.ProcessedDependencies) { return; } @@ -640,6 +615,26 @@ IDictionary variables } } + /// + /// Indicate which mode to use with this builder + /// + public enum Mode { + /// + /// Build the script + /// + Build, + + /// + /// Clean the command cache used to determine wheither a command has already been triggered. + /// + Clean, + + /// + /// Clean the command cache and delete every output objects + /// + CleanAndDelete + } + class ExecuteContext : IExecuteContext { readonly Builder builder; readonly BuilderContext builderContext; diff --git a/Rin.BuildEngine.Common/CommandIOMonitor.cs b/Rin.BuildEngine.Common/CommandIOMonitor.cs new file mode 100644 index 0000000..a7416c2 --- /dev/null +++ b/Rin.BuildEngine.Common/CommandIOMonitor.cs @@ -0,0 +1,160 @@ +using Rin.Core.Storage; +using Rin.Core.TODO; +using Serilog; +using System.Diagnostics; + +namespace Rin.BuildEngine.Common; + +/// +/// This class monitors input/output access from every BuildStep execution, and display an error message if an object +/// url is the input of a command and the output of another command running at the same time. +/// +class CommandIOMonitor { + /// + /// A dictionary containing read and write access timings (value) of a given object url (key) + /// + readonly Dictionary objectsAccesses = new(); + + /// + /// A dictionary containing execution intervals of BuildStep + /// + readonly Dictionary commandExecutionIntervals = new(); + + readonly Dictionary> commandInputFiles = new(); + + readonly ILogger logger; + + readonly object lockObject = new(); + + readonly Stopwatch stopWatch = new(); + + // Store earliest start time of command still running (to clean up accesses as time goes) + long earliestCommandAliveStartTime; + + public CommandIOMonitor(ILogger logger) { + this.logger = logger; + stopWatch.Start(); + } + + public void CommandStarted(CommandBuildStep command) { + lock (lockObject) { + var startTime = stopWatch.ElapsedTicks; + commandExecutionIntervals.Add(command, new TimeInterval(startTime)); + + // Get a list of unique input files + var inputFiles = command.Command.GetInputFiles().Distinct().ToList(); + // Store it aside, so that we're sure to remove the same entries during CommandEnded + commandInputFiles.Add(command, inputFiles); + + // Setup start read time for each file entry + var inputHash = new HashSet(); + foreach (var inputUrl in inputFiles) { + if (inputHash.Contains(inputUrl)) { + logger.Error( + $"The command '{command.Title}' has several times the file '{inputUrl.Path}' as input. Input Files must not be duplicated" + ); + } + + inputHash.Add(inputUrl); + + ObjectAccesses inputAccesses; + if (!objectsAccesses.TryGetValue(inputUrl, out inputAccesses)) { + objectsAccesses.Add(inputUrl, inputAccesses = new()); + } + + inputAccesses.Reads.Add(new TimeInterval(command, startTime)); + } + } + } + + public void CommandEnded(CommandBuildStep command) { + lock (lockObject) { + TimeInterval commandInterval = commandExecutionIntervals[command]; + + long startTime = commandInterval.StartTime; + var endTime = stopWatch.ElapsedTicks; + commandInterval.End(endTime); + + commandExecutionIntervals.Remove(command); + + foreach (var outputObject in command.Result.OutputObjects) { + var outputUrl = outputObject.Key; + if (objectsAccesses.TryGetValue(outputUrl, out var inputAccess)) { + foreach (TimeInterval input in inputAccess.Reads.Where( + input => input.Object != command && input.Overlap(startTime, endTime) + )) { + logger.Error( + $"Command {command} is writing {outputUrl} while command {input.Object} is reading it" + ); + } + } + + if (!objectsAccesses.TryGetValue(outputUrl, out var outputAccess)) { + objectsAccesses.Add(outputUrl, outputAccess = new()); + } + + foreach (var output in outputAccess.Writes.Where( + output => output.Object.Key != command && output.Overlap(startTime, endTime) + )) { + if (outputObject.Value != output.Object.Value) { + logger.Error( + $"Commands {command} and {output.Object} are both writing {outputUrl} at the same time, but they are different objects" + ); + } + } + + outputAccess.Writes.Add( + new TimeInterval>( + new KeyValuePair(command, outputObject.Value), + startTime, + endTime + ) + ); + } + + foreach (var inputUrl in command.Result.InputDependencyVersions.Keys) { + if (objectsAccesses.TryGetValue(inputUrl, out var outputAccess)) { + foreach (TimeInterval> output in outputAccess.Writes.Where( + output => output.Object.Key != command && output.Overlap(startTime, endTime) + )) { + logger.Error( + $"Command {output.Object} is writing {inputUrl} while command {command} is reading it" + ); + } + } + } + + // Notify that we're done reading input files + if (commandInputFiles.TryGetValue(command, out var inputFiles)) { + commandInputFiles.Remove(command); + foreach (var input in inputFiles) { + objectsAccesses[input].Reads.Single(x => x.Object == command).End(endTime); + } + } + + // "Garbage collection" of accesses + var newEarliestCommandAliveStartTime = commandExecutionIntervals.Count > 0 + ? commandExecutionIntervals.Min(x => x.Value.StartTime) + : endTime; + if (newEarliestCommandAliveStartTime > earliestCommandAliveStartTime) { + earliestCommandAliveStartTime = newEarliestCommandAliveStartTime; + + // We can remove objects whose all R/W accesses are "completed" (EndTime is set) + // and happened before all the current running commands started, since they won't affect us + foreach (var objectAccesses in objectsAccesses.ToList()) { + if (objectAccesses.Value.Reads.All(x => x.EndTime != 0 && x.EndTime < earliestCommandAliveStartTime) + && objectAccesses.Value.Writes.All( + x => x.EndTime != 0 && x.EndTime < earliestCommandAliveStartTime + )) { + objectsAccesses.Remove(objectAccesses.Key); + } + } + } + } + } + + class ObjectAccesses { + public List> Reads { get; } = new(); + public List>> Writes { get; } = new(); + } +} diff --git a/Rin.BuildEngine.Common/TimeInterval.cs b/Rin.BuildEngine.Common/TimeInterval.cs new file mode 100644 index 0000000..0734fa4 --- /dev/null +++ b/Rin.BuildEngine.Common/TimeInterval.cs @@ -0,0 +1,46 @@ +namespace Rin.BuildEngine.Common; + +/// +/// An helper class used to store command timing +/// +public class TimeInterval { + const long IntervalNotEnded = long.MaxValue; + public long StartTime { get; private set; } + public long EndTime { get; private set; } = IntervalNotEnded; + + public bool HasEnded => EndTime != IntervalNotEnded; + + public TimeInterval(long startTime) { + StartTime = startTime; + } + + public TimeInterval(long startTime, long endTime) { + StartTime = startTime; + EndTime = endTime; + } + + public void End(long endTime) { + if (EndTime != IntervalNotEnded) { + throw new InvalidOperationException("TimeInterval has already ended"); + } + + EndTime = endTime; + } + + public bool Overlap(long startTime, long endTime) => + (StartTime > startTime ? StartTime : startTime) < (EndTime < endTime ? EndTime : endTime); +} + +public class TimeInterval : TimeInterval { + public T Object { get; protected set; } + + public TimeInterval(T obj, long startTime) + : base(startTime) { + Object = obj; + } + + public TimeInterval(T obj, long startTime, long endTime) + : base(startTime, endTime) { + Object = obj; + } +} diff --git a/Rin.Core.Serialization/Storage/BundleOdbBackend.cs b/Rin.Core.Serialization/Storage/BundleOdbBackend.cs index d235e8d..3aaa796 100644 --- a/Rin.Core.Serialization/Storage/BundleOdbBackend.cs +++ b/Rin.Core.Serialization/Storage/BundleOdbBackend.cs @@ -1,4 +1,4 @@ -using CommunityToolkit.HighPerformance; +using Rin.Core.Extensions; using Rin.Core.IO; using Rin.Core.Serialization.Binary; using Rin.Core.Serialization.LZ4; diff --git a/Rin.Core/Extensions/ArrayExtensions.cs b/Rin.Core/Extensions/ArrayExtensions.cs new file mode 100644 index 0000000..44c44c2 --- /dev/null +++ b/Rin.Core/Extensions/ArrayExtensions.cs @@ -0,0 +1,29 @@ +namespace Rin.Core.Extensions; + +public static class ArrayExtensions { + /// + /// Deeply compares of two . + /// + /// Type of the object to compare + /// The list1 to compare + /// The list2 to compare + /// The comparer to use (or default to the default EqualityComparer for T) + /// true if the list are equal + public static bool ArraysEqual(IList? a1, IList? a2, IEqualityComparer? comparer = null) { + // This is not really an extension method, maybe it should go somewhere else. + if (ReferenceEquals(a1, a2)) { + return true; + } + + if (a1 == null || a2 == null) { + return false; + } + + if (a1.Count != a2.Count) { + return false; + } + + comparer ??= EqualityComparer.Default; + return !a1.Where((t, i) => !comparer.Equals(t, a2[i])).Any(); + } +}