diff --git a/src/Managing.Application/Backtests/BacktestExecutor.cs b/src/Managing.Application/Backtests/BacktestExecutor.cs index 58709d4e..60b6d602 100644 --- a/src/Managing.Application/Backtests/BacktestExecutor.cs +++ b/src/Managing.Application/Backtests/BacktestExecutor.cs @@ -16,52 +16,6 @@ using static Managing.Common.Enums; namespace Managing.Application.Backtests; -/// -/// Signal caching optimization to reduce redundant calculations -/// -public class SignalCache -{ - private readonly Dictionary> _cachedSignals = new(); - private readonly int _cacheSize = 50; // Cache last N candle signals to balance memory vs performance - private int _nextCacheKey = 0; - - public bool TryGetCachedSignal(int cacheKey, IndicatorType indicatorType, out object signal) - { - if (_cachedSignals.TryGetValue(cacheKey, out var candleSignals) && - candleSignals.TryGetValue(indicatorType, out signal)) - { - return true; - } - - signal = null; - return false; - } - - public int CacheSignal(IndicatorType indicatorType, object signal) - { - var cacheKey = _nextCacheKey++; - if (!_cachedSignals.ContainsKey(cacheKey)) - _cachedSignals[cacheKey] = new Dictionary(); - - _cachedSignals[cacheKey][indicatorType] = signal; - - // Maintain cache size - remove oldest entries - if (_cachedSignals.Count > _cacheSize) - { - var oldestKey = _cachedSignals.Keys.Min(); - _cachedSignals.Remove(oldestKey); - } - - return cacheKey; - } - - public void Clear() - { - _cachedSignals.Clear(); - _nextCacheKey = 0; - } -} - /// /// Comprehensive telemetry data for backtest execution profiling /// @@ -95,7 +49,6 @@ public class BacktestExecutor private readonly IScenarioService _scenarioService; private readonly IAccountService _accountService; private readonly IMessengerService _messengerService; - private readonly SignalCache _signalCache = new(); public BacktestExecutor( ILogger logger, @@ -177,59 +130,16 @@ public class BacktestExecutor _logger.LogInformation("Backtest requested by {UserId} with {TotalCandles} candles for {Ticker} on {Timeframe}", user.Id, totalCandles, config.Ticker, config.Timeframe); - // Pre-calculate indicator values once for all candles to optimize performance - // This avoids recalculating indicators for every candle iteration - Dictionary preCalculatedIndicatorValues = null; - if (config.Scenario != null && false) - { - var indicatorCalcStart = Stopwatch.GetTimestamp(); - - try - { - _logger.LogInformation("⚡ Pre-calculating indicator values for {IndicatorCount} indicators", - config.Scenario.Indicators?.Count ?? 0); - - // Convert LightScenario to Scenario for CalculateIndicatorsValues - var scenario = config.Scenario.ToScenario(); - - // Calculate all indicator values once with all candles - preCalculatedIndicatorValues = TradingBox.CalculateIndicatorsValues(scenario, candles); - telemetry.IndicatorPreCalculationTime = Stopwatch.GetElapsedTime(indicatorCalcStart); - _logger.LogInformation( - "✅ Successfully pre-calculated indicator values for {IndicatorCount} indicator types in {Duration:F2}ms", - preCalculatedIndicatorValues?.Count ?? 0, telemetry.IndicatorPreCalculationTime.TotalMilliseconds); - } - catch (Exception ex) - { - telemetry.IndicatorPreCalculationTime = Stopwatch.GetElapsedTime(indicatorCalcStart); - _logger.LogWarning(ex, - "❌ Failed to pre-calculate indicator values in {Duration:F2}ms, will calculate on-the-fly. Error: {ErrorMessage}", - telemetry.IndicatorPreCalculationTime.TotalMilliseconds, ex.Message); - // Continue with normal calculation if pre-calculation fails - preCalculatedIndicatorValues = null; - } - } - // Initialize wallet balance with first candle tradingBot.WalletBalances.Clear(); - tradingBot.WalletBalances.Add(candles.FirstOrDefault()!.Date, config.BotTradingBalance); + tradingBot.WalletBalances.Add(candles.First().Date, config.BotTradingBalance); var initialBalance = config.BotTradingBalance; - // Pre-allocate and populate candle structures for maximum performance - var orderedCandles = candles.ToList(); - - // Skip pre-calculated signals - the approach was flawed and caused performance regression - // The signal calculation depends on rolling window state and cannot be pre-calculated effectively - // Use optimized rolling window approach - TradingBox.GetSignal only needs last 600 candles - // Use List directly to preserve chronological order and enable incremental updates - const int RollingWindowSize = 600; // TradingBox.GetSignal only needs last 600 candles - var rollingWindowCandles = new List(RollingWindowSize); // Pre-allocate capacity for performance + const int RollingWindowSize = 600; + var rollingWindowCandles = new List(RollingWindowSize); // Pre-allocate capacity var candlesProcessed = 0; - // Signal caching optimization - reduce signal update frequency for better performance - var signalUpdateSkipCount = 0; - var lastProgressUpdate = DateTime.UtcNow; const int progressUpdateIntervalMs = 5000; // Update progress every 5 seconds to reduce database load const int walletCheckInterval = 10; // Check wallet balance every N candles instead of every candle @@ -247,14 +157,23 @@ public class BacktestExecutor var backtestStepTotalTime = TimeSpan.Zero; var progressCallbackTotalTime = TimeSpan.Zero; - _logger.LogInformation("🔄 Starting candle processing for {CandleCount} candles", orderedCandles.Count); + _logger.LogInformation("🔄 Starting candle processing for {CandleCount} candles", candles.Count); + + // TIMING: Track rolling window operations + var rollingWindowTotalTime = TimeSpan.Zero; + var loopOverheadTotalTime = TimeSpan.Zero; // Process all candles with optimized rolling window approach - foreach (var candle in orderedCandles) + foreach (var candle in candles) { + var loopStart = Stopwatch.GetTimestamp(); + // Check for cancellation (timeout or shutdown) cancellationToken.ThrowIfCancellationRequested(); + // TIMING: Measure rolling window operations + var rollingWindowStart = Stopwatch.GetTimestamp(); + // Maintain rolling window of last 600 candles to prevent exponential memory growth // Incremental updates: remove oldest if at capacity, then add newest // This preserves chronological order and avoids expensive HashSet recreation @@ -263,13 +182,15 @@ public class BacktestExecutor rollingWindowCandles.RemoveAt(0); // Remove oldest candle (O(n) but only 600 items max) } rollingWindowCandles.Add(candle); // Add newest candle (O(1) amortized) + + rollingWindowTotalTime += Stopwatch.GetElapsedTime(rollingWindowStart); tradingBot.LastCandle = candle; // Run with optimized backtest path (minimize async calls) var signalUpdateStart = Stopwatch.GetTimestamp(); // Pass List directly - no conversion needed, order is preserved - await tradingBot.UpdateSignals(rollingWindowCandles, preCalculatedIndicatorValues); + await tradingBot.UpdateSignals(rollingWindowCandles); signalUpdateTotalTime += Stopwatch.GetElapsedTime(signalUpdateStart); var backtestStepStart = Stopwatch.GetTimestamp(); @@ -338,6 +259,11 @@ public class BacktestExecutor "Backtest progress: {Percentage}% ({CurrentCandle}/{TotalCandles} candles processed)", currentPercentage, currentCandle, totalCandles); } + + // TIMING: Calculate loop overhead (everything except signal updates and backtest steps) + var loopTotal = Stopwatch.GetElapsedTime(loopStart); + var signalAndBacktestTime = signalUpdateTotalTime + backtestStepTotalTime; + // Note: loopOverheadTotalTime is cumulative, we track it at the end } // Complete candle processing telemetry @@ -347,6 +273,23 @@ public class BacktestExecutor telemetry.ProgressCallbackTime = progressCallbackTotalTime; telemetry.TotalCandlesProcessed = candlesProcessed; + // TIMING: Log detailed breakdown + _logger.LogInformation("📊 === DETAILED TIMING BREAKDOWN ==="); + _logger.LogInformation(" • Rolling Window Operations: {Time:F2}ms ({Percentage:F1}% of total)", + rollingWindowTotalTime.TotalMilliseconds, + rollingWindowTotalTime.TotalMilliseconds / telemetry.CandleProcessingTime.TotalMilliseconds * 100); + _logger.LogInformation(" • Signal Updates: {Time:F2}ms ({Percentage:F1}% of total)", + signalUpdateTotalTime.TotalMilliseconds, + signalUpdateTotalTime.TotalMilliseconds / telemetry.CandleProcessingTime.TotalMilliseconds * 100); + _logger.LogInformation(" • Backtest Steps (Run): {Time:F2}ms ({Percentage:F1}% of total)", + backtestStepTotalTime.TotalMilliseconds, + backtestStepTotalTime.TotalMilliseconds / telemetry.CandleProcessingTime.TotalMilliseconds * 100); + var accountedTime = rollingWindowTotalTime + signalUpdateTotalTime + backtestStepTotalTime + progressCallbackTotalTime; + var unaccountedTime = telemetry.CandleProcessingTime - accountedTime; + _logger.LogInformation(" • Other Loop Overhead: {Time:F2}ms ({Percentage:F1}% of total)", + unaccountedTime.TotalMilliseconds, + unaccountedTime.TotalMilliseconds / telemetry.CandleProcessingTime.TotalMilliseconds * 100); + _logger.LogInformation("✅ Backtest processing completed. Calculating final results..."); // Start result calculation timing @@ -445,14 +388,10 @@ public class BacktestExecutor telemetry.CandleProcessingTime.TotalMilliseconds, telemetry.CandleProcessingTime.TotalMilliseconds / totalExecutionTime.TotalMilliseconds * 100); _logger.LogInformation( - " • Signal Updates: {Time:F2}ms ({Percentage:F1}%) - {Count} updates, {SkipCount} skipped ({Efficiency:F1}% efficiency)", + " • Signal Updates: {Time:F2}ms ({Percentage:F1}%) - {Count} updates", telemetry.SignalUpdateTime.TotalMilliseconds, telemetry.SignalUpdateTime.TotalMilliseconds / totalExecutionTime.TotalMilliseconds * 100, - telemetry.TotalSignalUpdates, - signalUpdateSkipCount, - signalUpdateSkipCount > 0 - ? (double)signalUpdateSkipCount / (telemetry.TotalSignalUpdates + signalUpdateSkipCount) * 100 - : 0); + telemetry.TotalSignalUpdates); _logger.LogInformation(" • Backtest Steps: {Time:F2}ms ({Percentage:F1}%) - {Count} steps", telemetry.BacktestStepTime.TotalMilliseconds, telemetry.BacktestStepTime.TotalMilliseconds / totalExecutionTime.TotalMilliseconds * 100, diff --git a/src/Managing.Application/Bots/FuturesBot.cs b/src/Managing.Application/Bots/FuturesBot.cs index 30ec37e7..eb815702 100644 --- a/src/Managing.Application/Bots/FuturesBot.cs +++ b/src/Managing.Application/Bots/FuturesBot.cs @@ -511,9 +511,13 @@ public class FuturesBot : TradingBotBase if (riskResult.ShouldAutoClose && !string.IsNullOrEmpty(riskResult.EmergencyMessage)) { await LogWarningAsync(riskResult.EmergencyMessage); - await CloseTrade(Signals[position.SignalIdentifier], position, - position.StopLoss, - currentPrice, true); + // OPTIMIZATION 3: Use TryGetValue instead of direct dictionary access + if (Signals.TryGetValue(position.SignalIdentifier, out var positionSignal)) + { + await CloseTrade(positionSignal, position, + position.StopLoss, + currentPrice, true); + } } } diff --git a/src/Managing.Application/Bots/TradingBotBase.cs b/src/Managing.Application/Bots/TradingBotBase.cs index 8545f436..0761225a 100644 --- a/src/Managing.Application/Bots/TradingBotBase.cs +++ b/src/Managing.Application/Bots/TradingBotBase.cs @@ -47,6 +47,9 @@ public abstract class TradingBotBase : ITradingBot public Guid Identifier { get; set; } = Guid.Empty; public Candle LastCandle { get; set; } public DateTime? LastPositionClosingTime { get; set; } + + // OPTIMIZATION 2: Cache open position state to avoid expensive Positions.Any() calls + private bool _hasOpenPosition = false; public TradingBotBase( ILogger logger, @@ -264,12 +267,13 @@ public abstract class TradingBotBase : ITradingBot protected virtual async Task UpdateSignalsCore(IReadOnlyList candles, Dictionary preCalculatedIndicatorValues = null) { + // OPTIMIZATION 2: Use cached open position state instead of expensive Positions.Any() call // Skip indicator checking if flipping is disabled and there's an open position // This prevents unnecessary indicator calculations when we can't act on signals anyway - if (!Config.FlipPosition && Positions.Any(p => p.Value.IsOpen())) + if (!Config.FlipPosition && _hasOpenPosition) { Logger.LogDebug( - $"Skipping signal update: Position open and flip disabled. Open positions: {Positions.Count(p => p.Value.IsOpen())}"); + $"Skipping signal update: Position open and flip disabled."); return; } @@ -338,20 +342,19 @@ public abstract class TradingBotBase : ITradingBot protected async Task ManagePositions() { - // Early exit optimization - skip if no positions to manage - // Optimized: Use for loop to avoid multiple iterations - bool hasOpenPositions = false; + // OPTIMIZATION 6: Combine early exit checks and collect unfinished positions in one pass + // Collect unfinished positions in first iteration to avoid LINQ Where() later + var unfinishedPositions = new List(); foreach (var position in Positions.Values) { if (!position.IsFinished()) { - hasOpenPositions = true; - break; + unfinishedPositions.Add(position); } } bool hasWaitingSignals = false; - if (!hasOpenPositions) // Only check signals if no open positions + if (unfinishedPositions.Count == 0) // Only check signals if no open positions { foreach (var signal in Signals.Values) { @@ -363,14 +366,14 @@ public abstract class TradingBotBase : ITradingBot } } - if (!hasOpenPositions && !hasWaitingSignals) + if (unfinishedPositions.Count == 0 && !hasWaitingSignals) return; // First, process all existing positions that are not finished - foreach (var position in Positions.Values.Where(p => !p.IsFinished())) + foreach (var position in unfinishedPositions) { - var signalForPosition = Signals[position.SignalIdentifier]; - if (signalForPosition == null) + // OPTIMIZATION 3: Use TryGetValue instead of direct dictionary access + if (!Signals.TryGetValue(position.SignalIdentifier, out var signalForPosition)) { await LogInformation( $"🔍 Signal Recovery\nSignal not found for position `{position.Identifier}`\nRecreating signal from position data..."); @@ -873,7 +876,13 @@ public abstract class TradingBotBase : ITradingBot if (openedPosition != null) { - var previousSignal = Signals[openedPosition.SignalIdentifier]; + // OPTIMIZATION 3: Use TryGetValue instead of direct dictionary access + if (!Signals.TryGetValue(openedPosition.SignalIdentifier, out var previousSignal)) + { + // Signal not found, expire new signal and return + SetSignalStatus(signal.Identifier, SignalStatus.Expired); + return null; + } if (openedPosition.OriginDirection == signal.Direction) { @@ -908,6 +917,9 @@ public abstract class TradingBotBase : ITradingBot { // Add position to internal collection before any status updates Positions[position.Identifier] = position; + + // OPTIMIZATION 2: Update cached open position state + _hasOpenPosition = true; if (position.Open.Status != TradeStatus.Cancelled && position.Status != PositionStatus.Rejected) { @@ -1229,6 +1241,9 @@ public abstract class TradingBotBase : ITradingBot SkipCandleBasedCalculation: await SetPositionStatus(position.SignalIdentifier, PositionStatus.Finished); + + // OPTIMIZATION 2: Update cached open position state after closing position + _hasOpenPosition = Positions.Values.Any(p => p.IsOpen()); // Update position in database with all trade changes if (TradingBox.IsLiveTrading(Config.TradingType)) @@ -1413,9 +1428,10 @@ public abstract class TradingBotBase : ITradingBot protected void SetSignalStatus(string signalIdentifier, SignalStatus signalStatus) { - if (Signals.ContainsKey(signalIdentifier) && Signals[signalIdentifier].Status != signalStatus) + // OPTIMIZATION 4: Use TryGetValue instead of ContainsKey + direct access (single lookup) + if (Signals.TryGetValue(signalIdentifier, out var signal) && signal.Status != signalStatus) { - Signals[signalIdentifier].Status = signalStatus; + signal.Status = signalStatus; Logger.LogDebug($"Signal {signalIdentifier} is now {signalStatus}"); } } @@ -1470,6 +1486,13 @@ public abstract class TradingBotBase : ITradingBot { try { + // OPTIMIZATION 1: Early return for backtest - skip all logging and validation + if (TradingBox.IsBacktestTrading(Config.TradingType)) + { + Signals.Add(signal.Identifier, signal); + return; + } + // Set signal status based on configuration if (Config.IsForWatchingOnly || (ExecutionCount < 1 && TradingBox.IsLiveTrading(Config.TradingType))) { diff --git a/src/Managing.Workers.Tests/performance-benchmarks-two-scenarios.csv b/src/Managing.Workers.Tests/performance-benchmarks-two-scenarios.csv index fe0916e3..7f481bea 100644 --- a/src/Managing.Workers.Tests/performance-benchmarks-two-scenarios.csv +++ b/src/Managing.Workers.Tests/performance-benchmarks-two-scenarios.csv @@ -20,3 +20,5 @@ DateTime,TestName,CandlesCount,ExecutionTimeSeconds,ProcessingRateCandlesPerSec, 2025-12-01T10:50:46Z,Telemetry_ETH_RSI_EMACROSS,5760,2.30,2508.3,28.92,37.35,39.50,0.0,0,0.0,0.0,0.0,0.0,-30567.20,20,-45.32,0.00,93dc3e37,refactor-trading-bot,development 2025-12-19T10:11:32Z,Telemetry_ETH_RSI_EMACROSS,5760,18.57,310.2,28.99,14.21,35.78,0.0,0,0.0,0.0,0.0,0.0,-30567.20,20,-45.32,0.00,b52f00a4,dev,development 2025-12-19T10:54:33Z,Telemetry_ETH_RSI_EMACROSS,5760,4.93,1167.2,29.23,13.62,38.13,0.0,0,0.0,0.0,0.0,0.0,-30567.20,20,-45.32,0.00,b52f00a4,dev,development +2025-12-20T03:01:11Z,Telemetry_ETH_RSI_EMACROSS,5760,2.22,2599.7,29.25,21.79,35.44,0.0,0,0.0,0.0,0.0,0.0,-30567.20,20,-45.32,0.00,415845ed,dev,development +2025-12-20T03:03:51Z,Telemetry_ETH_RSI_EMACROSS,5760,3.98,1447.6,29.22,12.80,38.66,0.0,0,0.0,0.0,0.0,0.0,-30567.20,20,-45.32,0.00,415845ed,dev,development diff --git a/src/Managing.Workers.Tests/performance-benchmarks.csv b/src/Managing.Workers.Tests/performance-benchmarks.csv index 51d558c9..6b79f5a8 100644 --- a/src/Managing.Workers.Tests/performance-benchmarks.csv +++ b/src/Managing.Workers.Tests/performance-benchmarks.csv @@ -23,3 +23,6 @@ DateTime,TestName,CandlesCount,ExecutionTimeSeconds,ProcessingRateCandlesPerSec, 2025-12-01T10:50:46Z,Telemetry_ETH_RSI,5760,1.67,3442.1,28.90,23.95,41.13,1548.30,0,0.0,78.60,0.00,0.01,-9933.44,26,-36.30,0.00,93dc3e37,refactor-trading-bot,development 2025-12-19T10:11:32Z,Telemetry_ETH_RSI,5760,8.885,647.5,29.01,23.79,40.69,7622.36,0,0.0,879.40,0.00,0.15,-9933.44,26,-36.30,0.00,b52f00a4,dev,development 2025-12-19T10:54:33Z,Telemetry_ETH_RSI,5760,8.05,713.6,29.03,15.69,33.22,6980.81,0,0.0,802.29,0.00,0.14,-9933.44,26,-36.30,0.00,b52f00a4,dev,development +2025-12-19T14:33:20Z,Telemetry_ETH_RSI,5760,6.385,896.9,29.01,15.55,33.20,5470.73,0,0.0,617.39,0.00,0.11,-9933.44,26,-36.30,0.00,415845ed,dev,development +2025-12-20T03:01:11Z,Telemetry_ETH_RSI,5760,1.595,3602.9,29.24,13.93,41.99,1475.81 1475.81,0,0.0,74.04,0.00,0.01,-9933.44,26,-36.30,0.00,415845ed,dev,development +2025-12-20T03:03:51Z,Telemetry_ETH_RSI,5760,1.885,3052.6,29.22,22.05,43.48,1695.19 1695.19,0,0.0,114.09,0.00,0.02,-9933.44,26,-36.30,0.00,415845ed,dev,development