From 99ec3cd355b00933230ece789184f9fba4b674b6 Mon Sep 17 00:00:00 2001 From: Ske Date: Mon, 12 Aug 2019 02:05:30 +0200 Subject: [PATCH] Instrument and log database queries --- PluralKit.Bot/Bot.cs | 10 --- PluralKit.Bot/BotMetrics.cs | 3 +- PluralKit.Core/CoreMetrics.cs | 4 +- PluralKit.Core/Utils.cs | 160 ++++++++++++++++++++++++++++++++-- 4 files changed, 158 insertions(+), 19 deletions(-) diff --git a/PluralKit.Bot/Bot.cs b/PluralKit.Bot/Bot.cs index 00c31373..aeb0a46b 100644 --- a/PluralKit.Bot/Bot.cs +++ b/PluralKit.Bot/Bot.cs @@ -364,16 +364,6 @@ namespace PluralKit.Bot private void RegisterMessageMetrics(SocketMessage msg) { - var guild = (msg.Channel as IGuildChannel)?.Guild; - if (guild != null) - { - var shard = _client.GetShardFor(guild); - var latencyMillis = shard.Latency; - - _metrics.Provider.Timer.Instance(BotMetrics.GatewayLatency, new MetricTags("shard", shard.ShardId.ToString())) - .Record(latencyMillis, TimeUnit.Milliseconds); - } - _metrics.Measure.Meter.Mark(BotMetrics.MessagesReceived); } diff --git a/PluralKit.Bot/BotMetrics.cs b/PluralKit.Bot/BotMetrics.cs index e335c653..4f0080df 100644 --- a/PluralKit.Bot/BotMetrics.cs +++ b/PluralKit.Bot/BotMetrics.cs @@ -17,7 +17,6 @@ namespace PluralKit.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 TimerOptions WebhookResponseTime => new TimerOptions { Name = "Webhook Response Time", Context = "Bot" }; - public static TimerOptions GatewayLatency => new TimerOptions { Name = "Gateway Latency", Context = "Bot" }; + public static TimerOptions WebhookResponseTime => new TimerOptions { Name = "Webhook Response Time", Context = "Bot", RateUnit = TimeUnit.Seconds, MeasurementUnit = Unit.Requests, DurationUnit = TimeUnit.Seconds }; } } \ No newline at end of file diff --git a/PluralKit.Core/CoreMetrics.cs b/PluralKit.Core/CoreMetrics.cs index a8850296..e876c991 100644 --- a/PluralKit.Core/CoreMetrics.cs +++ b/PluralKit.Core/CoreMetrics.cs @@ -1,6 +1,7 @@ using App.Metrics; using App.Metrics.Gauge; using App.Metrics.Meter; +using App.Metrics.Timer; namespace PluralKit.Core { @@ -18,7 +19,8 @@ namespace PluralKit.Core public static GaugeOptions ProcessHandles => new GaugeOptions { Name = "Process Handle Count", MeasurementUnit = Unit.Items, Context = "Process" }; public static GaugeOptions CpuUsage => new GaugeOptions { Name = "CPU Usage", MeasurementUnit = Unit.Percent, Context = "Process" }; - public static MeterOptions DatabaseRequests => new MeterOptions() { Name = "Database Requests", MeasurementUnit = Unit.Requests, Context = "Database" }; + public static MeterOptions DatabaseRequests => new MeterOptions() { Name = "Database Requests", MeasurementUnit = Unit.Requests, Context = "Database", RateUnit = TimeUnit.Seconds}; + public static TimerOptions DatabaseQuery => new TimerOptions() { Name = "Database Query", MeasurementUnit = Unit.Requests, DurationUnit = TimeUnit.Seconds, RateUnit = TimeUnit.Seconds, Context = "Database" }; public static GaugeOptions DatabaseConnections => new GaugeOptions() { Name = "Database Connections", MeasurementUnit = Unit.Connections, Context = "Database" }; } } \ No newline at end of file diff --git a/PluralKit.Core/Utils.cs b/PluralKit.Core/Utils.cs index 249fb786..327feeae 100644 --- a/PluralKit.Core/Utils.cs +++ b/PluralKit.Core/Utils.cs @@ -1,6 +1,8 @@ using System; using System.Collections.Generic; using System.Data; +using System.Data.Common; +using System.Diagnostics; using System.IO; using System.Linq; using System.Security.Cryptography; @@ -8,6 +10,7 @@ using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; using App.Metrics; +using App.Metrics.Timer; using Dapper; using Microsoft.Extensions.Configuration; using Newtonsoft.Json; @@ -371,14 +374,16 @@ namespace PluralKit public class DbConnectionFactory { private CoreConfig _config; + private ILogger _logger; private IMetrics _metrics; private DbConnectionCountHolder _countHolder; - public DbConnectionFactory(CoreConfig config, DbConnectionCountHolder countHolder, IMetrics metrics) + public DbConnectionFactory(CoreConfig config, DbConnectionCountHolder countHolder, ILogger logger, IMetrics metrics) { _config = config; _countHolder = countHolder; _metrics = metrics; + _logger = logger; } public async Task Obtain() @@ -393,7 +398,7 @@ namespace PluralKit // Increment the count _countHolder.Increment(); // Return a wrapped connection which will decrement the counter on dispose - return new DbConnectionTrackingConnection(conn, _countHolder); + return new PerformanceTrackingConnection(conn, _countHolder, _logger, _metrics); } } @@ -413,17 +418,22 @@ namespace PluralKit } } - public class DbConnectionTrackingConnection: IDbConnection + public class PerformanceTrackingConnection: IDbConnection { // Simple delegation of everything. - private IDbConnection _impl; + private NpgsqlConnection _impl; private DbConnectionCountHolder _countHolder; + private ILogger _logger; + private IMetrics _metrics; - public DbConnectionTrackingConnection(IDbConnection impl, DbConnectionCountHolder countHolder) + public PerformanceTrackingConnection(NpgsqlConnection impl, DbConnectionCountHolder countHolder, + ILogger logger, IMetrics metrics) { _impl = impl; _countHolder = countHolder; + _logger = logger; + _metrics = metrics; } public void Dispose() @@ -455,7 +465,7 @@ namespace PluralKit public IDbCommand CreateCommand() { - return _impl.CreateCommand(); + return new PerformanceTrackingCommand(_impl.CreateCommand(), _logger, _metrics); } public void Open() @@ -476,6 +486,144 @@ namespace PluralKit public ConnectionState State => _impl.State; } + public class PerformanceTrackingCommand : DbCommand + { + private NpgsqlCommand _impl; + private ILogger _logger; + private IMetrics _metrics; + + public PerformanceTrackingCommand(NpgsqlCommand impl, ILogger logger, IMetrics metrics) + { + _impl = impl; + _metrics = metrics; + _logger = logger; + } + + public override void Cancel() + { + _impl.Cancel(); + } + + public override int ExecuteNonQuery() + { + return _impl.ExecuteNonQuery(); + } + + public override object ExecuteScalar() + { + return _impl.ExecuteScalar(); + } + + public override void Prepare() + { + _impl.Prepare(); + } + + public override string CommandText + { + get => _impl.CommandText; + set => _impl.CommandText = value; + } + + public override int CommandTimeout + { + get => _impl.CommandTimeout; + set => _impl.CommandTimeout = value; + } + + public override CommandType CommandType + { + get => _impl.CommandType; + set => _impl.CommandType = value; + } + + public override UpdateRowSource UpdatedRowSource + { + get => _impl.UpdatedRowSource; + set => _impl.UpdatedRowSource = value; + } + + protected override DbConnection DbConnection + { + get => _impl.Connection; + set => _impl.Connection = (NpgsqlConnection) value; + } + + protected override DbParameterCollection DbParameterCollection => _impl.Parameters; + + protected override DbTransaction DbTransaction + { + get => _impl.Transaction; + set => _impl.Transaction = (NpgsqlTransaction) value; + } + + public override bool DesignTimeVisible + { + get => _impl.DesignTimeVisible; + set => _impl.DesignTimeVisible = value; + } + + protected override DbParameter CreateDbParameter() + { + return _impl.CreateParameter(); + } + + protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) + { + return _impl.ExecuteReader(behavior); + } + + private IDisposable LogQuery() + { + return new QueryLogger(_logger, _metrics, CommandText); + } + + protected override async Task ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken) + { + using (LogQuery()) + return await _impl.ExecuteReaderAsync(behavior, cancellationToken); + } + + public override async Task ExecuteNonQueryAsync(CancellationToken cancellationToken) + { + using (LogQuery()) + return await _impl.ExecuteNonQueryAsync(cancellationToken); + } + + public override async Task ExecuteScalarAsync(CancellationToken cancellationToken) + { + using (LogQuery()) + return await _impl.ExecuteScalarAsync(cancellationToken); + } + } + + public class QueryLogger : IDisposable + { + private ILogger _logger; + private IMetrics _metrics; + private string _commandText; + private Stopwatch _stopwatch; + + public QueryLogger(ILogger logger, IMetrics metrics, string commandText) + { + _metrics = metrics; + _commandText = commandText; + _logger = logger; + + _stopwatch = new Stopwatch(); + _stopwatch.Start(); + } + + public void Dispose() + { + _stopwatch.Stop(); + _logger.Debug("Executed query {Query} in {ElapsedTime}", _commandText, _stopwatch.Elapsed); + + // One tick is 100 nanoseconds + _metrics.Provider.Timer.Instance(CoreMetrics.DatabaseQuery).Record(_stopwatch.ElapsedTicks / 10, TimeUnit.Microseconds, _commandText); + } + } + public class EventIdProvider { public Guid EventId { get; }