Add more performance metrics

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 ShardLatency => new GaugeOptions { Name = "Shard Latency", Context = "Bot"  };
-        public static GaugeOptions WebhookCacheSize => new GaugeOptions { Name = "Webhook Cache Size", Context = "Bot" };
+        public static GaugeOptions ShardsConnected => new GaugeOptions { Name = "Shards Connected", Context = "Bot", MeasurementUnit = Unit.Connections };
-        public static GaugeOptions WebhookRateLimitCacheSize => new GaugeOptions {Name = "Webhook Rate Limit Cache Size", Context = "Bot"};
+        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 };
     }
 }

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);

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);
         }
     }

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<ProxyService>();
         }
 
@@ -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<ProxyMember> 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;
 

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<int, ShardInfo> _shardInfo = new Dictionary<int, ShardInfo>();
         
-        public ShardInfoService(ILogger logger, DiscordShardedClient client)
+        public ShardInfoService(ILogger logger, DiscordShardedClient client, IMetrics metrics)
         {
             _client = client;
+            _metrics = metrics;
             _logger = logger.ForContext<ShardInfoService>();
         }
 
@@ -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; 
         }
 

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<ulong, Lazy<Task<DiscordWebhook>>> _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<WebhookCacheService>();
             _webhooks = new ConcurrentDictionary<ulong, Lazy<Task<DiscordWebhook>>>();
         }
@@ -78,6 +82,7 @@ namespace PluralKit.Bot
         private async Task<DiscordWebhook> 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);
         }
 

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
+            using (_metrics.Measure.Timer.Time(BotMetrics.WebhookResponseTime)) {
-            {
+                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)
                 {
-                    // Error 10015 = "Unknown Webhook" - this likely means the webhook was deleted
+                    response = await webhook.ExecuteAsync(dwb);
-                    // 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);
                 }
+                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;
+                    throw;
-            }
+                }
-
+            } 
-            timerCtx.Dispose();
 
             // 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);