From f2ed0a1f8d3d0f333665b8ec7b7c628ce59e2ccb Mon Sep 17 00:00:00 2001 From: Octol1ttle Date: Thu, 21 Dec 2023 23:38:04 +0500 Subject: [PATCH] feat: profile /about and /ban Signed-off-by: Octol1ttle --- src/Commands/AboutCommandGroup.cs | 31 +++++++--- src/Commands/BanCommandGroup.cs | 57 +++++++++++++++---- .../Events/ErrorLoggingPostExecutionEvent.cs | 19 +++++-- src/Services/Profiler/Profiler.cs | 45 +++++++++------ src/Services/Profiler/ProfilerEvent.cs | 1 + src/Services/Profiler/ProfilerFactory.cs | 2 - 6 files changed, 110 insertions(+), 45 deletions(-) diff --git a/src/Commands/AboutCommandGroup.cs b/src/Commands/AboutCommandGroup.cs index 4c396d9..9fc1f04 100644 --- a/src/Commands/AboutCommandGroup.cs +++ b/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; } /// @@ -65,25 +68,35 @@ public class AboutCommandGroup : CommandGroup [UsedImplicitly] public async Task 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 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)); } } diff --git a/src/Commands/BanCommandGroup.cs b/src/Commands/BanCommandGroup.cs index e72a43c..f27cb80 100644 --- a/src/Commands/BanCommandGroup.cs +++ b/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; } /// @@ -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 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)); } /// @@ -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) diff --git a/src/Commands/Events/ErrorLoggingPostExecutionEvent.cs b/src/Commands/Events/ErrorLoggingPostExecutionEvent.cs index 87cfc84..4abf95a 100644 --- a/src/Commands/Events/ErrorLoggingPostExecutionEvent.cs +++ b/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 _logger; private readonly IFeedbackService _feedback; + private readonly ILogger _logger; + private readonly Profiler _profiler; private readonly IDiscordRestUserAPI _userApi; public ErrorLoggingPostExecutionEvent(ILogger logger, IFeedbackService feedback, - IDiscordRestUserAPI userApi) + IDiscordRestUserAPI userApi, Profiler profiler) { _logger = logger; _feedback = feedback; _userApi = userApi; + _profiler = profiler; } /// @@ -43,6 +46,7 @@ public class ErrorLoggingPostExecutionEvent : IPostExecutionEvent public async Task 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)); } } diff --git a/src/Services/Profiler/Profiler.cs b/src/Services/Profiler/Profiler.cs index 8d4ca98..8e34540 100644 --- a/src/Services/Profiler/Profiler.cs +++ b/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; /// @@ -14,9 +11,10 @@ namespace Octobot.Services.Profiler; /// Resolve instead in singletons. public sealed class Profiler { - private const int MaxProfilerTime = 1000; // milliseconds + private const int MaxProfilerTime = 10; // milliseconds private readonly List _events = []; private readonly ILogger _logger; + private int _runningStopwatches; public Profiler(ILogger logger) { @@ -29,10 +27,12 @@ public sealed class Profiler /// The ID of the event. 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 /// Thrown if the profiler contains no events. 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; } /// /// If the profiler took too long to execute, this will log a warning with per-event time usage /// - /// + /// Thrown if there are stopwatches still running. 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) - { - throw new InvalidOperationException( - $"Tried to report on a profiler with running stopwatches: {profilerEvent.Id}"); - } - - builder.AppendLine($"{profilerEvent.Id}: {profilerEvent.Stopwatch.ElapsedMilliseconds}ms"); + builder.Append(' ', profilerEvent.NestingLevel * 4) + .AppendLine($"{profilerEvent.Id}: {profilerEvent.Stopwatch.ElapsedMilliseconds}ms"); unprofiled -= profilerEvent.Stopwatch.ElapsedMilliseconds; } - builder.AppendLine($": {unprofiled}ms"); + if (unprofiled > 0) + { + builder.AppendLine($": {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 /// /// the profiler and on it afterwards. /// - public void PopAndReport() + private void PopAndReport() { - Pop(); + while (_runningStopwatches > 0) + { + Pop(); + } + Report(); } diff --git a/src/Services/Profiler/ProfilerEvent.cs b/src/Services/Profiler/ProfilerEvent.cs index f655fc4..8b2ad84 100644 --- a/src/Services/Profiler/ProfilerEvent.cs +++ b/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; } } diff --git a/src/Services/Profiler/ProfilerFactory.cs b/src/Services/Profiler/ProfilerFactory.cs index 0135771..71a59c8 100644 --- a/src/Services/Profiler/ProfilerFactory.cs +++ b/src/Services/Profiler/ProfilerFactory.cs @@ -18,8 +18,6 @@ public sealed class ProfilerFactory /// Creates a new . /// /// A new . - // TODO: remove in future profiler PRs - // ReSharper disable once UnusedMember.Global public Profiler Create() { return _scopeFactory.CreateScope().ServiceProvider.GetRequiredService();