Merge pull request ppy#5322 from peppy/timed-task-loggin-improvement

Improve log output for too-many-scheduled-tasks
smoogipoo · Jul 25, 2022 · 391d4de · 391d4de
2 parents 7cd1118 + d2c85f9
commit 391d4de
Show file tree

Hide file tree

Showing 3 changed files with 30 additions and 25 deletions.
diff --git a/osu.Framework/Threading/ScheduledDelegate.cs b/osu.Framework/Threading/ScheduledDelegate.cs
@@ -1,8 +1,6 @@
 // Copyright (c) ppy Pty Ltd <contact@ppy.sh>. 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<ScheduledDelegate>
         /// <summary>
         /// The work task.
         /// </summary>
-        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();
+        }
 
         /// <summary>
         /// 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)
         {
@@ -139,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}";
+
         /// <summary>
         /// The current state of a scheduled delegate.
         /// </summary>

diff --git a/osu.Framework/Threading/ScheduledDelegateWithData.cs b/osu.Framework/Threading/ScheduledDelegateWithData.cs
@@ -1,8 +1,6 @@
 // Copyright (c) ppy Pty Ltd <contact@ppy.sh>. 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
@@ -21,5 +19,7 @@ public ScheduledDelegateWithData(Action<T> 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
@@ -1,13 +1,11 @@
 // Copyright (c) ppy Pty Ltd <contact@ppy.sh>. 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<ScheduledDelegate> timedTasks = new List<ScheduledDelegate>();
         private readonly List<ScheduledDelegate> perUpdateTasks = new List<ScheduledDelegate>();
 
-        private readonly Func<bool> isCurrentThread;
+        private readonly Func<bool>? 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()
         /// <summary>
         /// The base thread is assumed to be the thread on which the constructor is run.
         /// </summary>
-        public Scheduler(Func<bool> isCurrentThread, IClock clock)
+        public Scheduler(Func<bool>? 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()
         /// <param name="data">The data to be passed to the task.</param>
         /// <param name="forceScheduled">If set to false, the task will be executed immediately if we are on the main thread.</param>
         /// <returns>The scheduled task, or <c>null</c> if the task was executed immediately.</returns>
-        [CanBeNull]
-        public ScheduledDelegate Add<T>([NotNull] Action<T> task, T data, bool forceScheduled = true)
+        public ScheduledDelegate? Add<T>(Action<T> task, T data, bool forceScheduled = true)
         {
             if (!forceScheduled && IsMainThread)
             {
@@ -264,8 +262,7 @@ public ScheduledDelegate Add<T>([NotNull] Action<T> task, T data, bool forceSche
         /// <param name="task">The work to be done.</param>
         /// <param name="forceScheduled">If set to false, the task will be executed immediately if we are on the main thread.</param>
         /// <returns>The scheduled task, or <c>null</c> if the task was executed immediately.</returns>
-        [CanBeNull]
-        public ScheduledDelegate Add([NotNull] Action task, bool forceScheduled = true)
+        public ScheduledDelegate? Add(Action task, bool forceScheduled = true)
         {
             if (!forceScheduled && IsMainThread)
             {
@@ -287,16 +284,21 @@ public ScheduledDelegate Add([NotNull] Action task, bool forceScheduled = true)
         /// <remarks>The task will be run on the next <see cref="Update"/> independent of the current clock time.</remarks>
         /// <param name="task">The scheduled delegate to add.</param>
         /// <exception cref="InvalidOperationException">Thrown when attempting to add a scheduled delegate that has been already completed.</exception>
-        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)}");
 
             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()}", LoggingTarget.Performance);
+                    Logger.Log($"- Last task: {timedTasks.Last()}", LoggingTarget.Performance);
+                }
             }
         }
 
@@ -308,7 +310,7 @@ public void Add([NotNull] ScheduledDelegate task)
         /// <param name="timeUntilRun">Milliseconds until run.</param>
         /// <param name="repeat">Whether this task should repeat.</param>
         /// <returns>Whether this is the first queue attempt of this work.</returns>
-        public ScheduledDelegate AddDelayed<T>([NotNull] Action<T> task, T data, double timeUntilRun, bool repeat = false)
+        public ScheduledDelegate AddDelayed<T>(Action<T> 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)
@@ -326,8 +328,7 @@ public ScheduledDelegate AddDelayed<T>([NotNull] Action<T> task, T data, double
         /// <param name="timeUntilRun">Milliseconds until run.</param>
         /// <param name="repeat">Whether this task should repeat.</param>
         /// <returns>The scheduled task.</returns>
-        [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)
@@ -345,7 +346,7 @@ public ScheduledDelegate AddDelayed([NotNull] Action task, double timeUntilRun,
         /// <param name="task">The work to be done.</param>
         /// <param name="data">The data to be passed to the task. Note that duplicate schedules may result in previous data never being run.</param>
         /// <returns>Whether this is the first queue attempt of this work.</returns>
-        public bool AddOnce<T>([NotNull] Action<T> task, T data)
+        public bool AddOnce<T>(Action<T> task, T data)
         {
             lock (queueLock)
             {
@@ -370,7 +371,7 @@ public bool AddOnce<T>([NotNull] Action<T> task, T data)
         /// <remarks>The task will be run on the next <see cref="Update"/> independent of the current clock time.</remarks>
         /// <param name="task">The work to be done.</param>
         /// <returns>Whether this is the first queue attempt of this work.</returns>
-        public bool AddOnce([NotNull] Action task)
+        public bool AddOnce(Action task)
         {
             lock (queueLock)
             {