feat: profile /about and /ban

Signed-off-by: Octol1ttle <l1ttleofficial@outlook.com>

src/Commands/AboutCommandGroup.cs

@@ -4,6 +4,7 @@ using JetBrains.Annotations;
 using Octobot.Data;
 using Octobot.Extensions;
 using Octobot.Services;
+using Octobot.Services.Profiler;
 using Remora.Commands.Attributes;
 using Remora.Commands.Groups;
 using Remora.Discord.API.Abstractions.Objects;
@@ -36,20 +37,22 @@ public class AboutCommandGroup : CommandGroup
 
     private readonly ICommandContext _context;
     private readonly IFeedbackService _feedback;
-    private readonly GuildDataService _guildData;
-    private readonly IDiscordRestUserAPI _userApi;
     private readonly IDiscordRestGuildAPI _guildApi;
+    private readonly GuildDataService _guildData;
+    private readonly Profiler _profiler;
+    private readonly IDiscordRestUserAPI _userApi;
 
     public AboutCommandGroup(
         ICommandContext context, GuildDataService guildData,
         IFeedbackService feedback, IDiscordRestUserAPI userApi,
-        IDiscordRestGuildAPI guildApi)
+        IDiscordRestGuildAPI guildApi, Profiler profiler)
     {
         _context = context;
         _guildData = guildData;
         _feedback = feedback;
         _userApi = userApi;
         _guildApi = guildApi;
+        _profiler = profiler;
     }
 
     /// <summary>
@@ -65,25 +68,35 @@ public class AboutCommandGroup : CommandGroup
     [UsedImplicitly]
     public async Task<Result> ExecuteAboutAsync()
     {
+        _profiler.Push("about_command");
+        _profiler.Push("preparation");
         if (!_context.TryGetContextIDs(out var guildId, out _, out _))
         {
-            return new ArgumentInvalidError(nameof(_context), "Unable to retrieve necessary IDs from command context");
+            return _profiler.ReportWithResult(new ArgumentInvalidError(nameof(_context),
+                "Unable to retrieve necessary IDs from command context"));
         }
 
+        _profiler.Push("current_user_get");
         var botResult = await _userApi.GetCurrentUserAsync(CancellationToken);
         if (!botResult.IsDefined(out var bot))
         {
-            return Result.FromError(botResult);
+            return _profiler.ReportWithResult(Result.FromError(botResult));
         }
 
+        _profiler.Pop();
+        _profiler.Push("guild_settings_get");
         var cfg = await _guildData.GetSettings(guildId, CancellationToken);
         Messages.Culture = GuildSettings.Language.Get(cfg);
+        _profiler.Pop();
 
-        return await SendAboutBotAsync(bot, guildId, CancellationToken);
+        _profiler.Pop();
+        return _profiler.ReportWithResult(await SendAboutBotAsync(bot, guildId, CancellationToken));
     }
 
     private async Task<Result> SendAboutBotAsync(IUser bot, Snowflake guildId, CancellationToken ct = default)
     {
+        _profiler.Push("main");
+        _profiler.Push("builder_construction");
         var builder = new StringBuilder().Append("### ").AppendLine(Messages.AboutTitleDevelopers);
         foreach (var dev in Developers)
         {
@@ -96,6 +109,8 @@ public class AboutCommandGroup : CommandGroup
             builder.AppendBulletPointLine($"{tag} — {$"AboutDeveloper@{dev.Username}".Localized()}");
         }
 
+        _profiler.Pop();
+        _profiler.Push("embed_send");
         var embed = new EmbedBuilder()
             .WithSmallTitle(string.Format(Messages.AboutBot, bot.Username), bot)
             .WithDescription(builder.ToString())
@@ -117,10 +132,10 @@ public class AboutCommandGroup : CommandGroup
             URL: Octobot.IssuesUrl
         );
 
-        return await _feedback.SendContextualEmbedResultAsync(embed,
+        return _profiler.PopWithResult(await _feedback.SendContextualEmbedResultAsync(embed,
             new FeedbackMessageOptions(MessageComponents: new[]
             {
                 new ActionRowComponent(new[] { repositoryButton, issuesButton })
-            }), ct);
+            }), ct));
     }
 }

src/Commands/BanCommandGroup.cs

@@ -6,9 +6,11 @@ using Octobot.Data;
 using Octobot.Extensions;
 using Octobot.Parsers;
 using Octobot.Services;
+using Octobot.Services.Profiler;
 using Octobot.Services.Update;
 using Remora.Commands.Attributes;
 using Remora.Commands.Groups;
+using Remora.Commands.Parsers;
 using Remora.Discord.API.Abstractions.Objects;
 using Remora.Discord.API.Abstractions.Rest;
 using Remora.Discord.Commands.Attributes;
@@ -33,13 +35,14 @@ public class BanCommandGroup : CommandGroup
     private readonly IFeedbackService _feedback;
     private readonly IDiscordRestGuildAPI _guildApi;
     private readonly GuildDataService _guildData;
+    private readonly Profiler _profiler;
     private readonly IDiscordRestUserAPI _userApi;
     private readonly Utility _utility;
 
     public BanCommandGroup(
         ICommandContext context, IDiscordRestChannelAPI channelApi, GuildDataService guildData,
         IFeedbackService feedback, IDiscordRestGuildAPI guildApi, IDiscordRestUserAPI userApi,
-        Utility utility)
+        Utility utility, Profiler profiler)
     {
         _context = context;
         _channelApi = channelApi;
@@ -48,6 +51,7 @@ public class BanCommandGroup : CommandGroup
         _guildApi = guildApi;
         _userApi = userApi;
         _utility = utility;
+        _profiler = profiler;
     }
 
     /// <summary>
@@ -79,32 +83,43 @@ public class BanCommandGroup : CommandGroup
         [Description("Ban duration")] [Option("duration")]
         string? stringDuration = null)
     {
+        _profiler.Push("ban_command");
+        _profiler.Push("preparation");
         if (!_context.TryGetContextIDs(out var guildId, out var channelId, out var executorId))
         {
-            return new ArgumentInvalidError(nameof(_context), "Unable to retrieve necessary IDs from command context");
+            return _profiler.ReportWithResult(new ArgumentInvalidError(nameof(_context),
+                "Unable to retrieve necessary IDs from command context"));
         }
 
+        _profiler.Push("current_user_get");
         // The bot's avatar is used when sending error messages
         var botResult = await _userApi.GetCurrentUserAsync(CancellationToken);
         if (!botResult.IsDefined(out var bot))
         {
-            return Result.FromError(botResult);
+            return _profiler.ReportWithResult(Result.FromError(botResult));
         }
 
+        _profiler.Pop();
+        _profiler.Push("executor_get");
         var executorResult = await _userApi.GetUserAsync(executorId, CancellationToken);
         if (!executorResult.IsDefined(out var executor))
         {
-            return Result.FromError(executorResult);
+            return _profiler.ReportWithResult(Result.FromError(executorResult));
         }
 
+        _profiler.Pop();
+        _profiler.Push("guild_get");
         var guildResult = await _guildApi.GetGuildAsync(guildId, ct: CancellationToken);
         if (!guildResult.IsDefined(out var guild))
         {
-            return Result.FromError(guildResult);
+            return _profiler.ReportWithResult(Result.FromError(guildResult));
         }
 
+        _profiler.Pop();
+        _profiler.Push("guild_data_get");
         var data = await _guildData.GetData(guild.ID, CancellationToken);
         Messages.Culture = GuildSettings.Language.Get(data.Settings);
+        _profiler.Pop();
 
         if (stringDuration is null)
         {
@@ -127,18 +142,23 @@ public class BanCommandGroup : CommandGroup
     }
 
     private async Task<Result> BanUserAsync(
-        IUser executor, IUser target, string reason, TimeSpan? duration, IGuild guild, GuildData data, Snowflake channelId,
+        IUser executor, IUser target, string reason, TimeSpan? duration, IGuild guild, GuildData data,
+        Snowflake channelId,
         IUser bot, CancellationToken ct = default)
     {
+        _profiler.Push("main");
+        _profiler.Push("guild_ban_get");
         var existingBanResult = await _guildApi.GetGuildBanAsync(guild.ID, target.ID, ct);
         if (existingBanResult.IsDefined())
         {
             var failedEmbed = new EmbedBuilder().WithSmallTitle(Messages.UserAlreadyBanned, bot)
                 .WithColour(ColorsList.Red).Build();
 
-            return await _feedback.SendContextualEmbedResultAsync(failedEmbed, ct: ct);
+            return _profiler.PopWithResult(await _feedback.SendContextualEmbedResultAsync(failedEmbed, ct: ct));
         }
 
+        _profiler.Pop();
+        _profiler.Push("interactions_check");
         var interactionResult
             = await _utility.CheckInteractionsAsync(guild.ID, executor.ID, target.ID, "Ban", ct);
         if (!interactionResult.IsSuccess)
@@ -146,15 +166,19 @@ public class BanCommandGroup : CommandGroup
             return Result.FromError(interactionResult);
         }
 
+        _profiler.Pop();
         if (interactionResult.Entity is not null)
         {
+            _profiler.Push("error_embed_send");
             var errorEmbed = new EmbedBuilder().WithSmallTitle(interactionResult.Entity, bot)
                 .WithColour(ColorsList.Red).Build();
 
-            return await _feedback.SendContextualEmbedResultAsync(errorEmbed, ct: ct);
+            return _profiler.PopWithResult(await _feedback.SendContextualEmbedResultAsync(errorEmbed, ct: ct));
         }
 
-        var builder = new StringBuilder().AppendBulletPointLine(string.Format(Messages.DescriptionActionReason, reason));
+        _profiler.Push("builder_construction");
+        var builder =
+            new StringBuilder().AppendBulletPointLine(string.Format(Messages.DescriptionActionReason, reason));
         if (duration is not null)
         {
             builder.AppendBulletPoint(
@@ -166,9 +190,12 @@ public class BanCommandGroup : CommandGroup
         var title = string.Format(Messages.UserBanned, target.GetTag());
         var description = builder.ToString();
 
+        _profiler.Pop();
+        _profiler.Push("dm_create");
         var dmChannelResult = await _userApi.CreateDMAsync(target.ID, ct);
         if (dmChannelResult.IsDefined(out var dmChannel))
         {
+            _profiler.Push("dm_embed_send");
             var dmEmbed = new EmbedBuilder().WithGuildTitle(guild)
                 .WithTitle(Messages.YouWereBanned)
                 .WithDescription(description)
@@ -178,8 +205,11 @@ public class BanCommandGroup : CommandGroup
                 .Build();
 
             await _channelApi.CreateMessageWithEmbedResultAsync(dmChannel.ID, embedResult: dmEmbed, ct: ct);
+            _profiler.Pop();
         }
 
+        _profiler.Pop();
+        _profiler.Push("ban_create");
         var banResult = await _guildApi.CreateGuildBanAsync(
             guild.ID, target.ID, reason: $"({executor.GetTag()}) {reason}".EncodeHeader(),
             ct: ct);
@@ -193,10 +223,13 @@ public class BanCommandGroup : CommandGroup
             = duration is not null ? DateTimeOffset.UtcNow.Add(duration.Value) : DateTimeOffset.MaxValue;
         memberData.Roles.Clear();
 
+        _profiler.Pop();
+        _profiler.Push("embed_send");
         var embed = new EmbedBuilder().WithSmallTitle(
                 title, target)
             .WithColour(ColorsList.Green).Build();
 
+        _profiler.Push("action_log");
         var logResult = _utility.LogActionAsync(
             data.Settings, channelId, executor, title, description, target, ColorsList.Red, ct: ct);
         if (!logResult.IsSuccess)
@@ -204,7 +237,8 @@ public class BanCommandGroup : CommandGroup
             return Result.FromError(logResult.Error);
         }
 
-        return await _feedback.SendContextualEmbedResultAsync(embed, ct: ct);
+        _profiler.Pop();
+        return _profiler.PopWithResult(await _feedback.SendContextualEmbedResultAsync(embed, ct: ct));
     }
 
     /// <summary>
@@ -287,7 +321,8 @@ public class BanCommandGroup : CommandGroup
             .WithColour(ColorsList.Green).Build();
 
         var title = string.Format(Messages.UserUnbanned, target.GetTag());
-        var description = new StringBuilder().AppendBulletPoint(string.Format(Messages.DescriptionActionReason, reason));
+        var description =
+            new StringBuilder().AppendBulletPoint(string.Format(Messages.DescriptionActionReason, reason));
         var logResult = _utility.LogActionAsync(
             data.Settings, channelId, executor, title, description.ToString(), target, ColorsList.Green, ct: ct);
         if (!logResult.IsSuccess)

src/Commands/Events/ErrorLoggingPostExecutionEvent.cs

@@ -1,6 +1,7 @@
 using JetBrains.Annotations;
 using Microsoft.Extensions.Logging;
 using Octobot.Extensions;
+using Octobot.Services.Profiler;
 using Remora.Discord.API.Abstractions.Objects;
 using Remora.Discord.API.Abstractions.Rest;
 using Remora.Discord.API.Objects;
@@ -20,16 +21,18 @@ namespace Octobot.Commands.Events;
 [UsedImplicitly]
 public class ErrorLoggingPostExecutionEvent : IPostExecutionEvent
 {
-    private readonly ILogger<ErrorLoggingPostExecutionEvent> _logger;
     private readonly IFeedbackService _feedback;
+    private readonly ILogger<ErrorLoggingPostExecutionEvent> _logger;
+    private readonly Profiler _profiler;
     private readonly IDiscordRestUserAPI _userApi;
 
     public ErrorLoggingPostExecutionEvent(ILogger<ErrorLoggingPostExecutionEvent> logger, IFeedbackService feedback,
-        IDiscordRestUserAPI userApi)
+        IDiscordRestUserAPI userApi, Profiler profiler)
     {
         _logger = logger;
         _feedback = feedback;
         _userApi = userApi;
+        _profiler = profiler;
     }
 
     /// <summary>
@@ -43,6 +46,7 @@ public class ErrorLoggingPostExecutionEvent : IPostExecutionEvent
     public async Task<Result> AfterExecutionAsync(
         ICommandContext context, IResult commandResult, CancellationToken ct = default)
     {
+        _profiler.Push("post_command_execution");
         _logger.LogResult(commandResult, $"Error in slash command execution for /{context.Command.Command.Node.Key}.");
 
         var result = commandResult;
@@ -53,15 +57,18 @@ public class ErrorLoggingPostExecutionEvent : IPostExecutionEvent
 
         if (result.IsSuccess)
         {
-            return Result.FromSuccess();
+            return _profiler.ReportWithSuccess();
         }
 
+        _profiler.Push("current_user_get");
         var botResult = await _userApi.GetCurrentUserAsync(ct);
         if (!botResult.IsDefined(out var bot))
         {
-            return Result.FromError(botResult);
+            return _profiler.ReportWithResult(Result.FromError(botResult));
         }
 
+        _profiler.Pop();
+        _profiler.Push("embed_send");
         var embed = new EmbedBuilder().WithSmallTitle(Messages.CommandExecutionFailed, bot)
             .WithDescription(Markdown.InlineCode(result.Error.Message))
             .WithFooter(Messages.ContactDevelopers)
@@ -75,10 +82,10 @@ public class ErrorLoggingPostExecutionEvent : IPostExecutionEvent
             URL: Octobot.IssuesUrl
         );
 
-        return await _feedback.SendContextualEmbedResultAsync(embed,
+        return _profiler.ReportWithResult(await _feedback.SendContextualEmbedResultAsync(embed,
             new FeedbackMessageOptions(MessageComponents: new[]
             {
                 new ActionRowComponent(new[] { issuesButton })
-            }), ct);
+            }), ct));
     }
 }

src/Services/Profiler/Profiler.cs

@@ -3,9 +3,6 @@ using System.Text;
 using Microsoft.Extensions.Logging;
 using Remora.Results;
 
-// TODO: remove in future profiler PRs
-// ReSharper disable All
-
 namespace Octobot.Services.Profiler;
 
 /// <summary>
@@ -14,9 +11,10 @@ namespace Octobot.Services.Profiler;
 /// <remarks>Resolve <see cref="ProfilerFactory"/> instead in singletons.</remarks>
 public sealed class Profiler
 {
-    private const int MaxProfilerTime = 1000; // milliseconds
+    private const int MaxProfilerTime = 10; // milliseconds
     private readonly List<ProfilerEvent> _events = [];
     private readonly ILogger<Profiler> _logger;
+    private int _runningStopwatches;
 
     public Profiler(ILogger<Profiler> logger)
     {
@@ -29,10 +27,12 @@ public sealed class Profiler
     /// <param name="id">The ID of the event.</param>
     public void Push(string id)
     {
+        _runningStopwatches++;
         _events.Add(new ProfilerEvent
         {
             Id = id,
-            Stopwatch = Stopwatch.StartNew()
+            Stopwatch = Stopwatch.StartNew(),
+            NestingLevel = _runningStopwatches - 1
         });
     }
 
@@ -42,18 +42,25 @@ public sealed class Profiler
     /// <exception cref="InvalidOperationException">Thrown if the profiler contains no events.</exception>
     public void Pop()
     {
-        if (_events.Count is 0)
+        if (_runningStopwatches is 0)
         {
             throw new InvalidOperationException("Nothing to pop");
         }
 
-        _events.Last().Stopwatch.Stop();
+        _runningStopwatches--;
+        _events.FindLast(item => item.Stopwatch.IsRunning).Stopwatch.Stop();
+    }
+
+    public Result PopWithResult(Result result)
+    {
+        Pop();
+        return result;
     }
 
     /// <summary>
     /// If the profiler took too long to execute, this will log a warning with per-event time usage
     /// </summary>
-    /// <exception cref="InvalidOperationException"></exception>
+    /// <exception cref="InvalidOperationException">Thrown if there are stopwatches still running.</exception>
     private void Report()
     {
         var main = _events[0];
@@ -67,17 +74,15 @@ public sealed class Profiler
         for (var i = 1; i < _events.Count; i++)
         {
             var profilerEvent = _events[i];
-            if (profilerEvent.Stopwatch.IsRunning)
+            builder.Append(' ', profilerEvent.NestingLevel * 4)
-            {
+                .AppendLine($"{profilerEvent.Id}: {profilerEvent.Stopwatch.ElapsedMilliseconds}ms");
-                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");
+        if (unprofiled > 0)
+        {
+            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());
@@ -86,9 +91,13 @@ public sealed class Profiler
     /// <summary>
     /// <see cref="Pop"/> the profiler and <see cref="Report"/> on it afterwards.
     /// </summary>
-    public void PopAndReport()
+    private void PopAndReport()
     {
-        Pop();
+        while (_runningStopwatches > 0)
+        {
+            Pop();
+        }
+
         Report();
     }
 

src/Services/Profiler/ProfilerEvent.cs

@@ -6,4 +6,5 @@ public struct ProfilerEvent
 {
     public string Id { get; init; }
     public Stopwatch Stopwatch { get; init; }
+    public int NestingLevel { get; init; }
 }

src/Services/Profiler/ProfilerFactory.cs

@@ -18,8 +18,6 @@ public sealed class ProfilerFactory
     /// 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>();