From ca882dba732fd6e89d64daefab8a4580b2cf0cec Mon Sep 17 00:00:00 2001 From: Ske Date: Sun, 14 Jun 2020 22:19:12 +0200 Subject: [PATCH] Add more performance metrics --- PluralKit.Bot/BotMetrics.cs | 9 ++-- PluralKit.Bot/Handlers/MessageCreated.cs | 7 ++- PluralKit.Bot/Handlers/MessageEdited.cs | 11 +++- PluralKit.Bot/Proxy/ProxyService.cs | 13 ++++- PluralKit.Bot/Services/ShardInfoService.cs | 17 ++++++- PluralKit.Bot/Services/WebhookCacheService.cs | 7 ++- .../Services/WebhookExecutorService.cs | 51 +++++++++---------- 7 files changed, 79 insertions(+), 36 deletions(-) diff --git a/PluralKit.Bot/BotMetrics.cs b/PluralKit.Bot/BotMetrics.cs index 617ca307..ec34f48f 100644 --- a/PluralKit.Bot/BotMetrics.cs +++ b/PluralKit.Bot/BotMetrics.cs @@ -14,9 +14,12 @@ namespace PluralKit.Bot public static GaugeOptions MembersOnline => new GaugeOptions {Name = "Members online", MeasurementUnit = Unit.None, Context = "Bot"}; public static GaugeOptions Guilds => new GaugeOptions {Name = "Guilds", MeasurementUnit = Unit.None, Context = "Bot"}; public static GaugeOptions Channels => new GaugeOptions {Name = "Channels", MeasurementUnit = Unit.None, Context = "Bot"}; - public static GaugeOptions ShardsConnected => new GaugeOptions { Name = "Shards Connected", Context = "Bot" }; - public static GaugeOptions WebhookCacheSize => new GaugeOptions { Name = "Webhook Cache Size", Context = "Bot" }; - public static GaugeOptions WebhookRateLimitCacheSize => new GaugeOptions {Name = "Webhook Rate Limit Cache Size", Context = "Bot"}; + public static GaugeOptions ShardLatency => new GaugeOptions { Name = "Shard Latency", Context = "Bot" }; + public static GaugeOptions ShardsConnected => new GaugeOptions { Name = "Shards Connected", Context = "Bot", MeasurementUnit = Unit.Connections }; + public static MeterOptions WebhookCacheMisses => new MeterOptions { Name = "Webhook cache misses", Context = "Bot", MeasurementUnit = Unit.Calls }; + public static GaugeOptions WebhookCacheSize => new GaugeOptions { Name = "Webhook Cache Size", Context = "Bot", MeasurementUnit = Unit.Items }; public static TimerOptions WebhookResponseTime => new TimerOptions { Name = "Webhook Response Time", Context = "Bot", RateUnit = TimeUnit.Seconds, MeasurementUnit = Unit.Requests, DurationUnit = TimeUnit.Seconds }; + public static TimerOptions MessageContextQueryTime => new TimerOptions { Name = "Message context query duration", Context = "Bot", RateUnit = TimeUnit.Seconds, DurationUnit = TimeUnit.Seconds, MeasurementUnit = Unit.Calls }; + public static TimerOptions ProxyMembersQueryTime => new TimerOptions { Name = "Proxy member query duration", Context = "Bot", RateUnit = TimeUnit.Seconds, DurationUnit = TimeUnit.Seconds, MeasurementUnit = Unit.Calls }; } } \ No newline at end of file diff --git a/PluralKit.Bot/Handlers/MessageCreated.cs b/PluralKit.Bot/Handlers/MessageCreated.cs index ec4652a6..cdf778f0 100644 --- a/PluralKit.Bot/Handlers/MessageCreated.cs +++ b/PluralKit.Bot/Handlers/MessageCreated.cs @@ -55,8 +55,13 @@ namespace PluralKit.Bot _metrics.Measure.Meter.Mark(BotMetrics.MessagesReceived); _lastMessageCache.AddMessage(evt.Channel.Id, evt.Message.Id); + // Get message context from DB (tracking w/ metrics) + MessageContext ctx; + await using (var conn = await _db.Obtain()) + using (_metrics.Measure.Timer.Time(BotMetrics.MessageContextQueryTime)) + ctx = await conn.QueryMessageContext(evt.Author.Id, evt.Channel.GuildId, evt.Channel.Id); + // Try each handler until we find one that succeeds - var ctx = await _db.Execute(c => c.QueryMessageContext(evt.Author.Id, evt.Channel.GuildId, evt.Channel.Id)); var _ = await TryHandleLogClean(evt, ctx) || await TryHandleCommand(evt, ctx) || await TryHandleProxy(evt, ctx); diff --git a/PluralKit.Bot/Handlers/MessageEdited.cs b/PluralKit.Bot/Handlers/MessageEdited.cs index f1a3dca4..6ed1615b 100644 --- a/PluralKit.Bot/Handlers/MessageEdited.cs +++ b/PluralKit.Bot/Handlers/MessageEdited.cs @@ -1,5 +1,7 @@ using System.Threading.Tasks; +using App.Metrics; + using DSharpPlus.EventArgs; using PluralKit.Core; @@ -12,12 +14,14 @@ namespace PluralKit.Bot private readonly LastMessageCacheService _lastMessageCache; private readonly ProxyService _proxy; private readonly IDatabase _db; + private readonly IMetrics _metrics; - public MessageEdited(LastMessageCacheService lastMessageCache, ProxyService proxy, IDatabase db) + public MessageEdited(LastMessageCacheService lastMessageCache, ProxyService proxy, IDatabase db, IMetrics metrics) { _lastMessageCache = lastMessageCache; _proxy = proxy; _db = db; + _metrics = metrics; } public async Task Handle(MessageUpdateEventArgs evt) @@ -29,7 +33,10 @@ namespace PluralKit.Bot if (_lastMessageCache.GetLastMessage(evt.Channel.Id) != evt.Message.Id) return; // Just run the normal message handling code, with a flag to disable autoproxying - var ctx = await _db.Execute(c => c.QueryMessageContext(evt.Author.Id, evt.Channel.GuildId, evt.Channel.Id)); + MessageContext ctx; + await using (var conn = await _db.Obtain()) + using (_metrics.Measure.Timer.Time(BotMetrics.MessageContextQueryTime)) + ctx = await conn.QueryMessageContext(evt.Author.Id, evt.Channel.GuildId, evt.Channel.Id); await _proxy.HandleIncomingMessage(evt.Message, ctx, allowAutoproxy: false); } } diff --git a/PluralKit.Bot/Proxy/ProxyService.cs b/PluralKit.Bot/Proxy/ProxyService.cs index f87714d1..2f64adc6 100644 --- a/PluralKit.Bot/Proxy/ProxyService.cs +++ b/PluralKit.Bot/Proxy/ProxyService.cs @@ -1,7 +1,10 @@ using System; +using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using App.Metrics; + using DSharpPlus; using DSharpPlus.Entities; using DSharpPlus.Exceptions; @@ -22,15 +25,17 @@ namespace PluralKit.Bot private readonly ILogger _logger; private readonly WebhookExecutorService _webhookExecutor; private readonly ProxyMatcher _matcher; + private readonly IMetrics _metrics; public ProxyService(LogChannelService logChannel, IDataStore data, ILogger logger, - WebhookExecutorService webhookExecutor, IDatabase db, ProxyMatcher matcher) + WebhookExecutorService webhookExecutor, IDatabase db, ProxyMatcher matcher, IMetrics metrics) { _logChannel = logChannel; _data = data; _webhookExecutor = webhookExecutor; _db = db; _matcher = matcher; + _metrics = metrics; _logger = logger.ForContext(); } @@ -40,7 +45,11 @@ namespace PluralKit.Bot // Fetch members and try to match to a specific member await using var conn = await _db.Obtain(); - var members = (await conn.QueryProxyMembers(message.Author.Id, message.Channel.GuildId)).ToList(); + + List members; + using (_metrics.Measure.Timer.Time(BotMetrics.ProxyMembersQueryTime)) + members = (await conn.QueryProxyMembers(message.Author.Id, message.Channel.GuildId)).ToList(); + if (!_matcher.TryMatch(ctx, members, out var match, message.Content, message.Attachments.Count > 0, allowAutoproxy)) return false; diff --git a/PluralKit.Bot/Services/ShardInfoService.cs b/PluralKit.Bot/Services/ShardInfoService.cs index c7cde79e..cbfd3c39 100644 --- a/PluralKit.Bot/Services/ShardInfoService.cs +++ b/PluralKit.Bot/Services/ShardInfoService.cs @@ -1,6 +1,9 @@ using System.Collections.Generic; +using System.Linq; using System.Threading.Tasks; +using App.Metrics; + using DSharpPlus; using DSharpPlus.EventArgs; @@ -24,13 +27,15 @@ namespace PluralKit.Bot public bool Connected; } + private IMetrics _metrics; private ILogger _logger; private DiscordShardedClient _client; private Dictionary _shardInfo = new Dictionary(); - public ShardInfoService(ILogger logger, DiscordShardedClient client) + public ShardInfoService(ILogger logger, DiscordShardedClient client, IMetrics metrics) { _client = client; + _metrics = metrics; _logger = logger.ForContext(); } @@ -41,6 +46,13 @@ namespace PluralKit.Bot _client.SocketOpened += RefreshShardList; } + private void ReportShardStatus() + { + foreach (var (id, shard) in _shardInfo) + _metrics.Measure.Gauge.SetValue(BotMetrics.ShardLatency, new MetricTags("shard", id.ToString()), shard.ShardLatency.TotalMilliseconds); + _metrics.Measure.Gauge.SetValue(BotMetrics.ShardsConnected, _shardInfo.Count(s => s.Value.Connected)); + } + private async Task RefreshShardList() { // This callback doesn't actually receive the shard that was opening, so we just try to check we have 'em all (so far) @@ -95,6 +107,7 @@ namespace PluralKit.Bot var info = TryGetShard(e.Client); // info.LastConnectionTime = SystemClock.Instance.GetCurrentInstant(); info.Connected = true; + ReportShardStatus(); return Task.CompletedTask; } @@ -105,6 +118,7 @@ namespace PluralKit.Bot var info = TryGetShard(e.Client); info.LastConnectionTime = SystemClock.Instance.GetCurrentInstant(); info.Connected = true; + ReportShardStatus(); return Task.CompletedTask; } @@ -115,6 +129,7 @@ namespace PluralKit.Bot var info = TryGetShard(e.Client); info.DisconnectionCount++; info.Connected = false; + ReportShardStatus(); return Task.CompletedTask; } diff --git a/PluralKit.Bot/Services/WebhookCacheService.cs b/PluralKit.Bot/Services/WebhookCacheService.cs index 8967ee61..d1a65ca4 100644 --- a/PluralKit.Bot/Services/WebhookCacheService.cs +++ b/PluralKit.Bot/Services/WebhookCacheService.cs @@ -4,6 +4,8 @@ using System.Linq; using System.Net.Http; using System.Threading.Tasks; +using App.Metrics; + using DSharpPlus; using DSharpPlus.Entities; @@ -18,11 +20,13 @@ namespace PluralKit.Bot private DiscordShardedClient _client; private ConcurrentDictionary>> _webhooks; + private IMetrics _metrics; private ILogger _logger; - public WebhookCacheService(DiscordShardedClient client, ILogger logger) + public WebhookCacheService(DiscordShardedClient client, ILogger logger, IMetrics metrics) { _client = client; + _metrics = metrics; _logger = logger.ForContext(); _webhooks = new ConcurrentDictionary>>(); } @@ -78,6 +82,7 @@ namespace PluralKit.Bot private async Task GetOrCreateWebhook(DiscordChannel channel) { _logger.Debug("Webhook for channel {Channel} not found in cache, trying to fetch", channel.Id); + _metrics.Measure.Meter.Mark(BotMetrics.WebhookCacheMisses); return await FindExistingWebhook(channel) ?? await DoCreateWebhook(channel); } diff --git a/PluralKit.Bot/Services/WebhookExecutorService.cs b/PluralKit.Bot/Services/WebhookExecutorService.cs index 9a83b67b..62032ec9 100644 --- a/PluralKit.Bot/Services/WebhookExecutorService.cs +++ b/PluralKit.Bot/Services/WebhookExecutorService.cs @@ -13,6 +13,7 @@ using DSharpPlus.Exceptions; using Humanizer; using Newtonsoft.Json; +using Newtonsoft.Json.Serialization; using Serilog; @@ -72,36 +73,34 @@ namespace PluralKit.Bot await AddAttachmentsToBuilder(dwb, attachmentChunks[0]); } - var timerCtx = _metrics.Measure.Timer.Time(BotMetrics.WebhookResponseTime); - DiscordMessage response; - try - { - response = await webhook.ExecuteAsync(dwb); - } - catch (JsonReaderException) - { - // This happens sometimes when we hit a CloudFlare error (or similar) on Discord's end - // Nothing we can do about this - happens sometimes under server load, so just drop the message and give up - throw new WebhookExecutionErrorOnDiscordsEnd(); - } - catch (NotFoundException e) - { - var errorText = e.WebResponse?.Response; - if (errorText != null && errorText.Contains("10015") && !hasRetried) + using (_metrics.Measure.Timer.Time(BotMetrics.WebhookResponseTime)) { + try { - // Error 10015 = "Unknown Webhook" - this likely means the webhook was deleted - // but is still in our cache. Invalidate, refresh, try again - _logger.Warning("Error invoking webhook {Webhook} in channel {Channel}", webhook.Id, webhook.ChannelId); - - var newWebhook = await _webhookCache.InvalidateAndRefreshWebhook(channel, webhook); - return await ExecuteWebhookInner(channel, newWebhook, name, avatarUrl, content, attachments, hasRetried: true); + response = await webhook.ExecuteAsync(dwb); } + catch (JsonReaderException) + { + // This happens sometimes when we hit a CloudFlare error (or similar) on Discord's end + // Nothing we can do about this - happens sometimes under server load, so just drop the message and give up + throw new WebhookExecutionErrorOnDiscordsEnd(); + } + catch (NotFoundException e) + { + var errorText = e.WebResponse?.Response; + if (errorText != null && errorText.Contains("10015") && !hasRetried) + { + // Error 10015 = "Unknown Webhook" - this likely means the webhook was deleted + // but is still in our cache. Invalidate, refresh, try again + _logger.Warning("Error invoking webhook {Webhook} in channel {Channel}", webhook.Id, webhook.ChannelId); + + var newWebhook = await _webhookCache.InvalidateAndRefreshWebhook(channel, webhook); + return await ExecuteWebhookInner(channel, newWebhook, name, avatarUrl, content, attachments, hasRetried: true); + } - throw; - } - - timerCtx.Dispose(); + throw; + } + } // We don't care about whether the sending succeeds, and we don't want to *wait* for it, so we just fork it off var _ = TrySendRemainingAttachments(webhook, name, avatarUrl, attachmentChunks);