Refactor BacktestExecutor and TradingBotBase for performance optimizations; remove unused SignalCache and pre-calculation logic; implement caching for open position state and streamline signal access with TryGetValue; enhance logging for detailed timing breakdown during backtest execution.

2025-12-20 10:05:07 +07:00
parent 415845ed5a
commit e9b4878ffa
5 changed files with 91 additions and 120 deletions
--- 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;

-/// <summary>
-/// Signal caching optimization to reduce redundant calculations
-/// </summary>
-public class SignalCache
-{
-    private readonly Dictionary<int, Dictionary<IndicatorType, object>> _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<IndicatorType, object>();
-
-        _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;
-    }
-}
-
 /// <summary>
 /// Comprehensive telemetry data for backtest execution profiling
 /// </summary>
@@ -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<BacktestExecutor> 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<IndicatorType, IndicatorsResultBase> 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<Candle> directly to preserve chronological order and enable incremental updates
-        const int RollingWindowSize = 600; // TradingBox.GetSignal only needs last 600 candles
-        var rollingWindowCandles = new List<Candle>(RollingWindowSize); // Pre-allocate capacity for performance
+        const int RollingWindowSize = 600;
+        var rollingWindowCandles = new List<Candle>(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
@@ -264,12 +183,14 @@ public class BacktestExecutor
            }
            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<Candle> 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,
--- 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);
+            }
        }
    }

--- a/src/Managing.Application/Bots/TradingBotBase.cs
+++ b/src/Managing.Application/Bots/TradingBotBase.cs
@@ -48,6 +48,9 @@ public abstract class TradingBotBase : ITradingBot
    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<TradingBotBase> logger,
        IServiceScopeFactory scopeFactory,
@@ -264,12 +267,13 @@ public abstract class TradingBotBase : ITradingBot
    protected virtual async Task UpdateSignalsCore(IReadOnlyList<Candle> candles,
        Dictionary<IndicatorType, IndicatorsResultBase> 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<Position>();
        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)
            {
@@ -909,6 +918,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)
                    {
                        SetSignalStatus(signal.Identifier, SignalStatus.PositionOpen);
@@ -1230,6 +1242,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)))
            {
--- 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
--- 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