From d958bfc63ef9bf94044c2a2dedd2b7b928247251 Mon Sep 17 00:00:00 2001 From: Dean Herbert Date: Mon, 25 Jul 2022 16:12:54 +0900 Subject: [PATCH 1/3] Improve log output for too-many-scheduled-tasks ```csharp [performance] 2022-07-25 07:10:48 [verbose]: osu.Framework.Threading.Scheduler has 1000 timed tasks pending [performance] 2022-07-25 07:10:48 [verbose]: - First task: Void b__30_0() FPSCounter [performance] 2022-07-25 07:10:48 [verbose]: - Last task: Void b__30_0() FPSCounter ``` --- osu.Framework/Threading/Scheduler.cs | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/osu.Framework/Threading/Scheduler.cs b/osu.Framework/Threading/Scheduler.cs index 112172bc8c..9e92185f80 100644 --- a/osu.Framework/Threading/Scheduler.cs +++ b/osu.Framework/Threading/Scheduler.cs @@ -295,8 +295,13 @@ public void Add([NotNull] ScheduledDelegate task) lock (queueLock) { timedTasks.AddInPlace(task); + if (timedTasks.Count % LOG_EXCESSSIVE_QUEUE_LENGTH_INTERVAL == 0) + { Logger.Log($"{this} has {timedTasks.Count} timed tasks pending", LoggingTarget.Performance); + Logger.Log($"- First task: {timedTasks.First().Task.Method} targeting {timedTasks.First().Task.Target}", LoggingTarget.Performance); + Logger.Log($"- Last task: {timedTasks.Last().Task.Method} targeting {timedTasks.Last().Task.Target}", LoggingTarget.Performance); + } } } From 32cef654b0ae4b88ac49c78d5330e14bf15e33e3 Mon Sep 17 00:00:00 2001 From: Dean Herbert Date: Mon, 25 Jul 2022 16:36:54 +0900 Subject: [PATCH 2/3] Apply nullability to `Scheduler` and delegate classes --- osu.Framework/Threading/ScheduledDelegate.cs | 12 ++++--- .../Threading/ScheduledDelegateWithData.cs | 2 -- osu.Framework/Threading/Scheduler.cs | 36 +++++++++---------- 3 files changed, 23 insertions(+), 27 deletions(-) diff --git a/osu.Framework/Threading/ScheduledDelegate.cs b/osu.Framework/Threading/ScheduledDelegate.cs index a383e27e24..6c19bc22da 100644 --- a/osu.Framework/Threading/ScheduledDelegate.cs +++ b/osu.Framework/Threading/ScheduledDelegate.cs @@ -1,8 +1,6 @@ // Copyright (c) ppy Pty Ltd . Licensed under the MIT Licence. // See the LICENCE file in the repository root for full licence text. -#nullable disable - using System; using System.Diagnostics; @@ -42,7 +40,7 @@ public class ScheduledDelegate : IComparable /// /// The work task. /// - internal Action Task; + internal Action? Task; public ScheduledDelegate(Action task, double executionTime = 0, double repeatInterval = -1) : this(executionTime, repeatInterval) @@ -102,7 +100,11 @@ internal void RunTaskInternal() } } - protected virtual void InvokeTask() => Task(); + protected virtual void InvokeTask() + { + Debug.Assert(Task != null); + Task(); + } /// /// Cancel a task. @@ -118,7 +120,7 @@ public void Cancel() } } - public int CompareTo(ScheduledDelegate other) => ExecutionTime == other.ExecutionTime ? -1 : ExecutionTime.CompareTo(other.ExecutionTime); + public int CompareTo(ScheduledDelegate? other) => ExecutionTime == other?.ExecutionTime ? -1 : ExecutionTime.CompareTo(other?.ExecutionTime); internal void SetNextExecution(double? currentTime) { diff --git a/osu.Framework/Threading/ScheduledDelegateWithData.cs b/osu.Framework/Threading/ScheduledDelegateWithData.cs index dbd4ab353a..2fa39f8b47 100644 --- a/osu.Framework/Threading/ScheduledDelegateWithData.cs +++ b/osu.Framework/Threading/ScheduledDelegateWithData.cs @@ -1,8 +1,6 @@ // Copyright (c) ppy Pty Ltd . Licensed under the MIT Licence. // See the LICENCE file in the repository root for full licence text. -#nullable disable - using System; namespace osu.Framework.Threading diff --git a/osu.Framework/Threading/Scheduler.cs b/osu.Framework/Threading/Scheduler.cs index 9e92185f80..97451e999f 100644 --- a/osu.Framework/Threading/Scheduler.cs +++ b/osu.Framework/Threading/Scheduler.cs @@ -1,13 +1,11 @@ // Copyright (c) ppy Pty Ltd . Licensed under the MIT Licence. // See the LICENCE file in the repository root for full licence text. -#nullable disable - using System; using System.Collections.Generic; +using System.Diagnostics.CodeAnalysis; using System.Linq; using System.Threading; -using JetBrains.Annotations; using osu.Framework.Extensions; using osu.Framework.Logging; using osu.Framework.Timing; @@ -23,9 +21,10 @@ public class Scheduler private readonly List timedTasks = new List(); private readonly List perUpdateTasks = new List(); - private readonly Func isCurrentThread; + private readonly Func? isCurrentThread; + + private IClock? clock; - private IClock clock; private double currentTime => clock?.CurrentTime ?? 0; private readonly object queueLock = new object(); @@ -60,7 +59,7 @@ public Scheduler() /// /// The base thread is assumed to be the thread on which the constructor is run. /// - public Scheduler(Func isCurrentThread, IClock clock) + public Scheduler(Func? isCurrentThread, IClock clock) { this.isCurrentThread = isCurrentThread; this.clock = clock; @@ -121,7 +120,7 @@ public int Update() int countRun = 0; - while (getNextTask(out ScheduledDelegate sd)) + while (getNextTask(out ScheduledDelegate? sd)) { sd.RunTaskInternal(); @@ -204,7 +203,7 @@ private void queuePerUpdateTasks() } } - private bool getNextTask(out ScheduledDelegate task) + private bool getNextTask([NotNullWhen(true)] out ScheduledDelegate? task) { lock (queueLock) { @@ -240,8 +239,7 @@ public void CancelDelayedTasks() /// The data to be passed to the task. /// If set to false, the task will be executed immediately if we are on the main thread. /// The scheduled task, or null if the task was executed immediately. - [CanBeNull] - public ScheduledDelegate Add([NotNull] Action task, T data, bool forceScheduled = true) + public ScheduledDelegate? Add(Action task, T data, bool forceScheduled = true) { if (!forceScheduled && IsMainThread) { @@ -264,8 +262,7 @@ public ScheduledDelegate Add([NotNull] Action task, T data, bool forceSche /// The work to be done. /// If set to false, the task will be executed immediately if we are on the main thread. /// The scheduled task, or null if the task was executed immediately. - [CanBeNull] - public ScheduledDelegate Add([NotNull] Action task, bool forceScheduled = true) + public ScheduledDelegate? Add(Action task, bool forceScheduled = true) { if (!forceScheduled && IsMainThread) { @@ -287,7 +284,7 @@ public ScheduledDelegate Add([NotNull] Action task, bool forceScheduled = true) /// The task will be run on the next independent of the current clock time. /// The scheduled delegate to add. /// Thrown when attempting to add a scheduled delegate that has been already completed. - public void Add([NotNull] ScheduledDelegate task) + public void Add(ScheduledDelegate task) { if (task.Completed) throw new InvalidOperationException($"Can not add a {nameof(ScheduledDelegate)} that has been already {nameof(ScheduledDelegate.Completed)}"); @@ -299,8 +296,8 @@ public void Add([NotNull] ScheduledDelegate task) if (timedTasks.Count % LOG_EXCESSSIVE_QUEUE_LENGTH_INTERVAL == 0) { Logger.Log($"{this} has {timedTasks.Count} timed tasks pending", LoggingTarget.Performance); - Logger.Log($"- First task: {timedTasks.First().Task.Method} targeting {timedTasks.First().Task.Target}", LoggingTarget.Performance); - Logger.Log($"- Last task: {timedTasks.Last().Task.Method} targeting {timedTasks.Last().Task.Target}", LoggingTarget.Performance); + Logger.Log($"- First task: {timedTasks.First().Task?.Method} targeting {timedTasks.First().Task?.Target}", LoggingTarget.Performance); + Logger.Log($"- Last task: {timedTasks.Last().Task?.Method} targeting {timedTasks.Last().Task?.Target}", LoggingTarget.Performance); } } } @@ -313,7 +310,7 @@ public void Add([NotNull] ScheduledDelegate task) /// Milliseconds until run. /// Whether this task should repeat. /// Whether this is the first queue attempt of this work. - public ScheduledDelegate AddDelayed([NotNull] Action task, T data, double timeUntilRun, bool repeat = false) + public ScheduledDelegate AddDelayed(Action task, T data, double timeUntilRun, bool repeat = false) { // We are locking here already to make sure we have no concurrent access to currentTime lock (queueLock) @@ -331,8 +328,7 @@ public ScheduledDelegate AddDelayed([NotNull] Action task, T data, double /// Milliseconds until run. /// Whether this task should repeat. /// The scheduled task. - [NotNull] - public ScheduledDelegate AddDelayed([NotNull] Action task, double timeUntilRun, bool repeat = false) + public ScheduledDelegate AddDelayed(Action task, double timeUntilRun, bool repeat = false) { // We are locking here already to make sure we have no concurrent access to currentTime lock (queueLock) @@ -350,7 +346,7 @@ public ScheduledDelegate AddDelayed([NotNull] Action task, double timeUntilRun, /// The work to be done. /// The data to be passed to the task. Note that duplicate schedules may result in previous data never being run. /// Whether this is the first queue attempt of this work. - public bool AddOnce([NotNull] Action task, T data) + public bool AddOnce(Action task, T data) { lock (queueLock) { @@ -375,7 +371,7 @@ public bool AddOnce([NotNull] Action task, T data) /// The task will be run on the next independent of the current clock time. /// The work to be done. /// Whether this is the first queue attempt of this work. - public bool AddOnce([NotNull] Action task) + public bool AddOnce(Action task) { lock (queueLock) { From d2c85f9d1b70691c0b36c87b4939fe3af2029593 Mon Sep 17 00:00:00 2001 From: Dean Herbert Date: Mon, 25 Jul 2022 16:39:57 +0900 Subject: [PATCH 3/3] Move display logic to individual `ScheduledDelegate` implementations --- osu.Framework/Threading/ScheduledDelegate.cs | 2 ++ osu.Framework/Threading/ScheduledDelegateWithData.cs | 2 ++ osu.Framework/Threading/Scheduler.cs | 4 ++-- 3 files changed, 6 insertions(+), 2 deletions(-) diff --git a/osu.Framework/Threading/ScheduledDelegate.cs b/osu.Framework/Threading/ScheduledDelegate.cs index 6c19bc22da..13d02daf97 100644 --- a/osu.Framework/Threading/ScheduledDelegate.cs +++ b/osu.Framework/Threading/ScheduledDelegate.cs @@ -141,6 +141,8 @@ internal void SetNextExecution(double? currentTime) } } + public override string ToString() => $"method \"{Task?.Method}\" targeting \"{Task?.Target}\" executing at {ExecutionTime:N0} with repeat {RepeatInterval}"; + /// /// The current state of a scheduled delegate. /// diff --git a/osu.Framework/Threading/ScheduledDelegateWithData.cs b/osu.Framework/Threading/ScheduledDelegateWithData.cs index 2fa39f8b47..f50c8cda50 100644 --- a/osu.Framework/Threading/ScheduledDelegateWithData.cs +++ b/osu.Framework/Threading/ScheduledDelegateWithData.cs @@ -19,5 +19,7 @@ public ScheduledDelegateWithData(Action task, T data, double executionTime = } protected override void InvokeTask() => Task(Data); + + public override string ToString() => $"method \"{Task.Method}\" targeting \"{Task.Target}\" with data \"{Data}\" executing at {ExecutionTime:N0} with repeat {RepeatInterval}"; } } diff --git a/osu.Framework/Threading/Scheduler.cs b/osu.Framework/Threading/Scheduler.cs index 97451e999f..db27cb892c 100644 --- a/osu.Framework/Threading/Scheduler.cs +++ b/osu.Framework/Threading/Scheduler.cs @@ -296,8 +296,8 @@ public void Add(ScheduledDelegate task) if (timedTasks.Count % LOG_EXCESSSIVE_QUEUE_LENGTH_INTERVAL == 0) { Logger.Log($"{this} has {timedTasks.Count} timed tasks pending", LoggingTarget.Performance); - Logger.Log($"- First task: {timedTasks.First().Task?.Method} targeting {timedTasks.First().Task?.Target}", LoggingTarget.Performance); - Logger.Log($"- Last task: {timedTasks.Last().Task?.Method} targeting {timedTasks.Last().Task?.Target}", LoggingTarget.Performance); + Logger.Log($"- First task: {timedTasks.First()}", LoggingTarget.Performance); + Logger.Log($"- Last task: {timedTasks.Last()}", LoggingTarget.Performance); } } }