- Increased thresholds for maximum query and method executions per window to 500 and 250, respectively, to reduce false positives in loop detection. - Enabled logging of slow queries only, improving performance by reducing log volume. - Adjusted SQL query logging to capture only warnings and errors, further optimizing logging efficiency. - Updated various settings across appsettings files to reflect these changes, ensuring consistency in configuration.
227 lines
8.9 KiB
C#
227 lines
8.9 KiB
C#
using System.Collections.Concurrent;
|
|
using Microsoft.Extensions.Logging;
|
|
|
|
namespace Managing.Infrastructure.Databases.PostgreSql;
|
|
|
|
/// <summary>
|
|
/// Service for detecting potential SQL query loops and performance issues
|
|
/// Monitors query patterns and execution frequency to identify problematic operations
|
|
/// </summary>
|
|
public class SqlLoopDetectionService
|
|
{
|
|
private readonly ILogger<SqlLoopDetectionService> _logger;
|
|
private readonly ConcurrentDictionary<string, QueryExecutionTracker> _queryTrackers;
|
|
private readonly Timer _cleanupTimer;
|
|
private readonly TimeSpan _trackingWindow = TimeSpan.FromMinutes(5);
|
|
private readonly int _maxExecutionsPerWindow = 10;
|
|
private readonly TimeSpan _cleanupInterval = TimeSpan.FromMinutes(1);
|
|
|
|
public SqlLoopDetectionService(ILogger<SqlLoopDetectionService> logger)
|
|
{
|
|
_logger = logger;
|
|
_queryTrackers = new ConcurrentDictionary<string, QueryExecutionTracker>();
|
|
|
|
// Setup cleanup timer to remove old tracking data
|
|
_cleanupTimer = new Timer(CleanupOldTrackers, null, _cleanupInterval, _cleanupInterval);
|
|
}
|
|
|
|
/// <summary>
|
|
/// Tracks a query execution and detects potential loops
|
|
/// </summary>
|
|
/// <param name="repositoryName">Name of the repository executing the query</param>
|
|
/// <param name="methodName">Name of the method executing the query</param>
|
|
/// <param name="queryPattern">Pattern or hash of the query being executed</param>
|
|
/// <param name="executionTime">Time taken to execute the query</param>
|
|
/// <returns>True if a potential loop is detected</returns>
|
|
public bool TrackQueryExecution(string repositoryName, string methodName, string queryPattern,
|
|
TimeSpan executionTime)
|
|
{
|
|
var key = $"{repositoryName}.{methodName}.{queryPattern}";
|
|
var now = DateTime.UtcNow;
|
|
|
|
var tracker = _queryTrackers.AddOrUpdate(key,
|
|
new QueryExecutionTracker
|
|
{
|
|
RepositoryName = repositoryName,
|
|
MethodName = methodName,
|
|
QueryPattern = queryPattern,
|
|
FirstExecution = now,
|
|
LastExecution = now,
|
|
ExecutionCount = 1,
|
|
TotalExecutionTime = executionTime,
|
|
MaxExecutionTime = executionTime,
|
|
MinExecutionTime = executionTime
|
|
},
|
|
(k, existing) =>
|
|
{
|
|
existing.LastExecution = now;
|
|
existing.ExecutionCount++;
|
|
existing.TotalExecutionTime += executionTime;
|
|
existing.MaxExecutionTime = existing.MaxExecutionTime > executionTime
|
|
? existing.MaxExecutionTime
|
|
: executionTime;
|
|
existing.MinExecutionTime = existing.MinExecutionTime < executionTime
|
|
? existing.MinExecutionTime
|
|
: executionTime;
|
|
return existing;
|
|
});
|
|
|
|
// Check for potential loop conditions
|
|
var timeSinceFirst = now - tracker.FirstExecution;
|
|
var executionsPerMinute = tracker.ExecutionCount / Math.Max(timeSinceFirst.TotalMinutes, 0.1);
|
|
|
|
var isLoopDetected = false;
|
|
var reasons = new List<string>();
|
|
|
|
// Check execution frequency (increased threshold to reduce false positives)
|
|
if (executionsPerMinute > 100)
|
|
{
|
|
isLoopDetected = true;
|
|
reasons.Add($"High frequency: {executionsPerMinute:F1} executions/minute");
|
|
}
|
|
|
|
// Check total execution count in window
|
|
if (tracker.ExecutionCount > _maxExecutionsPerWindow)
|
|
{
|
|
isLoopDetected = true;
|
|
reasons.Add($"High count: {tracker.ExecutionCount} executions in {timeSinceFirst.TotalMinutes:F1} minutes");
|
|
}
|
|
|
|
// Check for rapid successive executions (increased threshold to reduce false positives)
|
|
if (tracker.ExecutionCount > 20 && timeSinceFirst.TotalSeconds < 10)
|
|
{
|
|
isLoopDetected = true;
|
|
reasons.Add(
|
|
$"Rapid execution: {tracker.ExecutionCount} executions in {timeSinceFirst.TotalSeconds:F1} seconds");
|
|
}
|
|
|
|
// Check for consistently slow queries (increased threshold to reduce false positives)
|
|
if (tracker.ExecutionCount > 10 && tracker.AverageExecutionTime.TotalMilliseconds > 1000)
|
|
{
|
|
isLoopDetected = true;
|
|
reasons.Add($"Consistently slow: {tracker.AverageExecutionTime.TotalMilliseconds:F0}ms average");
|
|
}
|
|
|
|
if (isLoopDetected)
|
|
{
|
|
_logger.LogWarning(
|
|
"[SQL-LOOP-DETECTED] {Repository}.{Method} | Pattern: {Pattern} | Count: {Count} | Reasons: {Reasons} | Avg Time: {AvgTime}ms",
|
|
repositoryName, methodName, queryPattern, tracker.ExecutionCount,
|
|
string.Join(", ", reasons), tracker.AverageExecutionTime.TotalMilliseconds);
|
|
|
|
// Log detailed execution history
|
|
_logger.LogWarning(
|
|
"[SQL-LOOP-DETAILS] {Repository}.{Method} | First: {First} | Last: {Last} | Min: {Min}ms | Max: {Max}ms | Total: {Total}ms",
|
|
repositoryName, methodName, tracker.FirstExecution.ToString("HH:mm:ss.fff"),
|
|
tracker.LastExecution.ToString("HH:mm:ss.fff"), tracker.MinExecutionTime.TotalMilliseconds,
|
|
tracker.MaxExecutionTime.TotalMilliseconds, tracker.TotalExecutionTime.TotalMilliseconds);
|
|
}
|
|
|
|
return isLoopDetected;
|
|
}
|
|
|
|
/// <summary>
|
|
/// Gets current statistics for all tracked queries
|
|
/// </summary>
|
|
public Dictionary<string, QueryExecutionStats> GetQueryStatistics()
|
|
{
|
|
var stats = new Dictionary<string, QueryExecutionStats>();
|
|
var now = DateTime.UtcNow;
|
|
|
|
foreach (var kvp in _queryTrackers)
|
|
{
|
|
var tracker = kvp.Value;
|
|
var timeSinceFirst = now - tracker.FirstExecution;
|
|
|
|
stats[kvp.Key] = new QueryExecutionStats
|
|
{
|
|
RepositoryName = tracker.RepositoryName,
|
|
MethodName = tracker.MethodName,
|
|
QueryPattern = tracker.QueryPattern,
|
|
ExecutionCount = tracker.ExecutionCount,
|
|
FirstExecution = tracker.FirstExecution,
|
|
LastExecution = tracker.LastExecution,
|
|
AverageExecutionTime = tracker.AverageExecutionTime,
|
|
MinExecutionTime = tracker.MinExecutionTime,
|
|
MaxExecutionTime = tracker.MaxExecutionTime,
|
|
ExecutionsPerMinute = tracker.ExecutionCount / Math.Max(timeSinceFirst.TotalMinutes, 0.1),
|
|
IsActive = timeSinceFirst < _trackingWindow
|
|
};
|
|
}
|
|
|
|
return stats;
|
|
}
|
|
|
|
/// <summary>
|
|
/// Clears all tracking data
|
|
/// </summary>
|
|
public void ClearAllTracking()
|
|
{
|
|
_queryTrackers.Clear();
|
|
_logger.LogInformation("[SQL-LOOP-DETECTION] All tracking data cleared");
|
|
}
|
|
|
|
private void CleanupOldTrackers(object? state)
|
|
{
|
|
var now = DateTime.UtcNow;
|
|
var keysToRemove = new List<string>();
|
|
|
|
foreach (var kvp in _queryTrackers)
|
|
{
|
|
var timeSinceLastExecution = now - kvp.Value.LastExecution;
|
|
if (timeSinceLastExecution > _trackingWindow)
|
|
{
|
|
keysToRemove.Add(kvp.Key);
|
|
}
|
|
}
|
|
|
|
foreach (var key in keysToRemove)
|
|
{
|
|
_queryTrackers.TryRemove(key, out _);
|
|
}
|
|
|
|
if (keysToRemove.Count > 0)
|
|
{
|
|
_logger.LogDebug("[SQL-LOOP-DETECTION] Cleaned up {Count} old trackers", keysToRemove.Count);
|
|
}
|
|
}
|
|
|
|
public void Dispose()
|
|
{
|
|
_cleanupTimer?.Dispose();
|
|
}
|
|
|
|
private class QueryExecutionTracker
|
|
{
|
|
public string RepositoryName { get; set; } = string.Empty;
|
|
public string MethodName { get; set; } = string.Empty;
|
|
public string QueryPattern { get; set; } = string.Empty;
|
|
public DateTime FirstExecution { get; set; }
|
|
public DateTime LastExecution { get; set; }
|
|
public int ExecutionCount { get; set; }
|
|
public TimeSpan TotalExecutionTime { get; set; }
|
|
public TimeSpan MaxExecutionTime { get; set; }
|
|
public TimeSpan MinExecutionTime { get; set; }
|
|
|
|
public TimeSpan AverageExecutionTime =>
|
|
ExecutionCount > 0 ? TimeSpan.FromTicks(TotalExecutionTime.Ticks / ExecutionCount) : TimeSpan.Zero;
|
|
}
|
|
}
|
|
|
|
/// <summary>
|
|
/// Statistics for query execution tracking
|
|
/// </summary>
|
|
public class QueryExecutionStats
|
|
{
|
|
public string RepositoryName { get; set; } = string.Empty;
|
|
public string MethodName { get; set; } = string.Empty;
|
|
public string QueryPattern { get; set; } = string.Empty;
|
|
public int ExecutionCount { get; set; }
|
|
public DateTime FirstExecution { get; set; }
|
|
public DateTime LastExecution { get; set; }
|
|
public TimeSpan AverageExecutionTime { get; set; }
|
|
public TimeSpan MinExecutionTime { get; set; }
|
|
public TimeSpan MaxExecutionTime { get; set; }
|
|
public double ExecutionsPerMinute { get; set; }
|
|
public bool IsActive { get; set; }
|
|
} |