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;
}
/// <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));
}
}
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;
}
/// <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)
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<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));
}
}
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;
/// <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)
- {
- 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>: {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();
}
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 <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>();