From 7d9a85d8156a15953f71fbe11bc13e6fa81f1bed Mon Sep 17 00:00:00 2001
From: Octol1ttle <l1ttleofficial@outlook.com>
Date: Wed, 20 Dec 2023 22:59:17 +0500
Subject: [PATCH] Add profiler base (#235)

This PR adds the base classes required for profiling code inside of
Octobot. The implementation of the profiler is similar to Minecraft,
however it is more detailed and provides per-event logs for each event.
This PR does not change any code to be profiled and this is intentional.
Changes required for profiling will come as separate PRs, one for
commands, one for responders, and one for background services.

Signed-off-by: Octol1ttle <l1ttleofficial@outlook.com>
---
 src/Octobot.cs                           |   3 +
 src/Services/Profiler/Profiler.cs        | 114 +++++++++++++++++++++++
 src/Services/Profiler/ProfilerEvent.cs   |   9 ++
 src/Services/Profiler/ProfilerFactory.cs |  27 ++++++
 4 files changed, 153 insertions(+)
 create mode 100644 src/Services/Profiler/Profiler.cs
 create mode 100644 src/Services/Profiler/ProfilerEvent.cs
 create mode 100644 src/Services/Profiler/ProfilerFactory.cs

diff --git a/src/Octobot.cs b/src/Octobot.cs
index 2e810ed..063bd14 100644
--- a/src/Octobot.cs
+++ b/src/Octobot.cs
@@ -4,6 +4,7 @@ using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
 using Octobot.Commands.Events;
 using Octobot.Services;
+using Octobot.Services.Profiler;
 using Octobot.Services.Update;
 using Remora.Discord.API.Abstractions.Gateway.Commands;
 using Remora.Discord.API.Abstractions.Objects;
@@ -86,6 +87,8 @@ public sealed class Octobot
                         .AddPreparationErrorEvent<LoggingPreparationErrorEvent>()
                         .AddPostExecutionEvent<ErrorLoggingPostExecutionEvent>()
                         // Services
+                        .AddTransient<Profiler>()
+                        .AddSingleton<ProfilerFactory>()
                         .AddSingleton<Utility>()
                         .AddSingleton<GuildDataService>()
                         .AddHostedService<GuildDataService>(provider => provider.GetRequiredService<GuildDataService>())
diff --git a/src/Services/Profiler/Profiler.cs b/src/Services/Profiler/Profiler.cs
new file mode 100644
index 0000000..8d4ca98
--- /dev/null
+++ b/src/Services/Profiler/Profiler.cs
@@ -0,0 +1,114 @@
+using System.Diagnostics;
+using System.Text;
+using Microsoft.Extensions.Logging;
+using Remora.Results;
+
+// TODO: remove in future profiler PRs
+// ReSharper disable All
+
+namespace Octobot.Services.Profiler;
+
+/// <summary>
+/// Provides the ability to profile how long certain parts of code take to complete using <see cref="Stopwatch"/>es.
+/// </summary>
+/// <remarks>Resolve <see cref="ProfilerFactory"/> instead in singletons.</remarks>
+public sealed class Profiler
+{
+    private const int MaxProfilerTime = 1000; // milliseconds
+    private readonly List<ProfilerEvent> _events = [];
+    private readonly ILogger<Profiler> _logger;
+
+    public Profiler(ILogger<Profiler> logger)
+    {
+        _logger = logger;
+    }
+
+    /// <summary>
+    /// Pushes an event to the profiler.
+    /// </summary>
+    /// <param name="id">The ID of the event.</param>
+    public void Push(string id)
+    {
+        _events.Add(new ProfilerEvent
+        {
+            Id = id,
+            Stopwatch = Stopwatch.StartNew()
+        });
+    }
+
+    /// <summary>
+    /// Pops the last pushed event from the profiler.
+    /// </summary>
+    /// <exception cref="InvalidOperationException">Thrown if the profiler contains no events.</exception>
+    public void Pop()
+    {
+        if (_events.Count is 0)
+        {
+            throw new InvalidOperationException("Nothing to pop");
+        }
+
+        _events.Last().Stopwatch.Stop();
+    }
+
+    /// <summary>
+    /// If the profiler took too long to execute, this will log a warning with per-event time usage
+    /// </summary>
+    /// <exception cref="InvalidOperationException"></exception>
+    private void Report()
+    {
+        var main = _events[0];
+        if (main.Stopwatch.ElapsedMilliseconds < MaxProfilerTime)
+        {
+            return;
+        }
+
+        var unprofiled = main.Stopwatch.ElapsedMilliseconds;
+        var builder = new StringBuilder().AppendLine();
+        for (var i = 1; i < _events.Count; i++)
+        {
+            var profilerEvent = _events[i];
+            if (profilerEvent.Stopwatch.IsRunning)
+            {
+                throw new InvalidOperationException(
+                    $"Tried to report on a profiler with running stopwatches: {profilerEvent.Id}");
+            }
+
+            builder.AppendLine($"{profilerEvent.Id}: {profilerEvent.Stopwatch.ElapsedMilliseconds}ms");
+            unprofiled -= profilerEvent.Stopwatch.ElapsedMilliseconds;
+        }
+
+        builder.AppendLine($"<unprofiled>: {unprofiled}ms");
+
+        _logger.LogWarning("Profiler {ID} took {Elapsed} milliseconds to execute (max: {Max}ms):{Events}", main.Id,
+            main.Stopwatch.ElapsedMilliseconds, MaxProfilerTime, builder.ToString());
+    }
+
+    /// <summary>
+    /// <see cref="Pop"/> the profiler and <see cref="Report"/> on it afterwards.
+    /// </summary>
+    public void PopAndReport()
+    {
+        Pop();
+        Report();
+    }
+
+    /// <summary>
+    /// <see cref="PopAndReport"/> on the profiler and return a <see cref="Result{TEntity}"/>.
+    /// </summary>
+    /// <param name="result"></param>
+    /// <returns></returns>
+    public Result ReportWithResult(Result result)
+    {
+        PopAndReport();
+        return result;
+    }
+
+    /// <summary>
+    /// Calls <see cref="ReportWithResult"/> with <see cref="Result.FromSuccess"/>
+    /// </summary>
+    /// <returns>A successful result.</returns>
+    public Result ReportWithSuccess()
+    {
+        return ReportWithResult(Result.FromSuccess());
+    }
+}
diff --git a/src/Services/Profiler/ProfilerEvent.cs b/src/Services/Profiler/ProfilerEvent.cs
new file mode 100644
index 0000000..f655fc4
--- /dev/null
+++ b/src/Services/Profiler/ProfilerEvent.cs
@@ -0,0 +1,9 @@
+using System.Diagnostics;
+
+namespace Octobot.Services.Profiler;
+
+public struct ProfilerEvent
+{
+    public string Id { get; init; }
+    public Stopwatch Stopwatch { get; init; }
+}
diff --git a/src/Services/Profiler/ProfilerFactory.cs b/src/Services/Profiler/ProfilerFactory.cs
new file mode 100644
index 0000000..0135771
--- /dev/null
+++ b/src/Services/Profiler/ProfilerFactory.cs
@@ -0,0 +1,27 @@
+using Microsoft.Extensions.DependencyInjection;
+
+namespace Octobot.Services.Profiler;
+
+/// <summary>
+/// Provides a method to create a <see cref="Profiler"/>. Useful in singletons.
+/// </summary>
+public sealed class ProfilerFactory
+{
+    private readonly IServiceScopeFactory _scopeFactory;
+
+    public ProfilerFactory(IServiceScopeFactory scopeFactory)
+    {
+        _scopeFactory = scopeFactory;
+    }
+
+    /// <summary>
+    /// Creates a new <see cref="Profiler"/>.
+    /// </summary>
+    /// <returns>A new <see cref="Profiler"/>.</returns>
+    // TODO: remove in future profiler PRs
+    // ReSharper disable once UnusedMember.Global
+    public Profiler Create()
+    {
+        return _scopeFactory.CreateScope().ServiceProvider.GetRequiredService<Profiler>();
+    }
+}