Add big-request guardrails and honest resource diagnostics

Algorithm/QCAlgorithm.History.cs

@@ -38,6 +38,8 @@ public partial class QCAlgorithm
 
         private bool _dataDictionaryTickWarningSent;
 
+        private readonly LargeHistoryRequestDiagnostics _largeHistoryRequestDiagnostics = new();
+
         /// <summary>
         /// Gets or sets the history provider for the algorithm
         /// </summary>
@@ -1019,7 +1021,9 @@ protected IEnumerable<DataDictionary<T>> GetDataTypedHistory<T>(IEnumerable<Hist
         private IEnumerable<Slice> History(IEnumerable<HistoryRequest> requests, DateTimeZone timeZone)
         {
             // filter out any universe securities that may have made it this far
-            var filteredRequests = GetFilterestRequests(requests);
+            var filteredRequests = GetFilterestRequests(requests).ToList();
+
+            _largeHistoryRequestDiagnostics.WarnOnLargeHistoryRequests(filteredRequests, Debug);
 
             // filter out future data to prevent look ahead bias
             var history = HistoryProvider.GetHistory(filteredRequests, timeZone);
@@ -1555,5 +1559,119 @@ private static IEnumerable<Slice> WrapPythonDataHistory(IEnumerable<Slice> histo
                 }
             }
         }
+
+        /// <summary>
+        /// One-time warnings for history requests likely to stall the algorithm or run it out of memory:
+        /// a single call over the cells threshold, or repeated large calls with overlapping time windows,
+        /// e.g. re-fetching a long lookback every day instead of updating incrementally
+        /// </summary>
+        private sealed class LargeHistoryRequestDiagnostics
+        {
+            private const int OverlappingRequestsWarningCount = 30;
+            private const int OverlappingRequestSizeDivisor = 50;
+            private const int AssumedTicksPerSecond = 10;
+
+            private readonly long _cellsWarningThreshold = Config.GetInt("history-request-cells-warning-threshold", 5000000);
+            private bool _largeRequestWarningSent;
+            private bool _overlappingRequestsWarningSent;
+            private int _consecutiveOverlappingRequests;
+            private DateTime _previousRequestStartUtc;
+            private DateTime _previousRequestEndUtc;
+
+            /// <summary>
+            /// Checks the given requests and emits the applicable warnings through the given debug callback
+            /// </summary>
+            public void WarnOnLargeHistoryRequests(List<HistoryRequest> requests, Action<string> debug)
+            {
+                try
+                {
+                    if (_largeRequestWarningSent && _overlappingRequestsWarningSent || requests.Count == 0)
+                    {
+                        return;
+                    }
+
+                    long estimatedCells = 0;
+                    var startUtc = DateTime.MaxValue;
+                    var endUtc = DateTime.MinValue;
+                    foreach (var request in requests)
+                    {
+                        estimatedCells += EstimateDataCells(request);
+                        if (request.StartTimeUtc < startUtc)
+                        {
+                            startUtc = request.StartTimeUtc;
+                        }
+                        if (request.EndTimeUtc > endUtc)
+                        {
+                            endUtc = request.EndTimeUtc;
+                        }
+                    }
+
+                    if (!_largeRequestWarningSent && estimatedCells >= _cellsWarningThreshold)
+                    {
+                        _largeRequestWarningSent = true;
+                        debug($"Warning: large history request, estimated at ~{estimatedCells.ToStringInvariant("N0")} data cells" +
+                            $" across {requests.Count} request(s). This can be slow and memory intensive: request fewer symbols," +
+                            " a shorter period or a coarser resolution.");
+                    }
+
+                    if (!_overlappingRequestsWarningSent && estimatedCells >= _cellsWarningThreshold / OverlappingRequestSizeDivisor)
+                    {
+                        var overlaps = startUtc < _previousRequestEndUtc && endUtc > _previousRequestStartUtc;
+                        _consecutiveOverlappingRequests = overlaps ? _consecutiveOverlappingRequests + 1 : 0;
+                        _previousRequestStartUtc = startUtc;
+                        _previousRequestEndUtc = endUtc;
+
+                        if (_consecutiveOverlappingRequests >= OverlappingRequestsWarningCount)
+                        {
+                            _overlappingRequestsWarningSent = true;
+                            debug($"Warning: history() has been called {OverlappingRequestsWarningCount}+ consecutive times with" +
+                                " overlapping time windows. Instead of re-fetching a long lookback, fetch it once and keep it updated" +
+                                " with a rolling window, consolidators or indicator warm up.");
+                        }
+                    }
+                }
+                catch (Exception exception)
+                {
+                    // diagnostics must never interfere with the algorithm: log, disable and move on
+                    _largeRequestWarningSent = true;
+                    _overlappingRequestsWarningSent = true;
+                    QuantConnect.Logging.Log.Error(exception);
+                }
+            }
+
+            /// <summary>
+            /// Rough order-of-magnitude estimate of the data cells (bars x columns) a history request will produce
+            /// </summary>
+            private static long EstimateDataCells(HistoryRequest request)
+            {
+                var span = request.EndTimeUtc - request.StartTimeUtc;
+                if (span <= TimeSpan.Zero)
+                {
+                    return 0;
+                }
+
+                // ~5 tradable days a week; sub-daily resolutions only have data during regular market hours
+                var tradableDays = Math.Max(1, span.TotalDays * 5 / 7);
+                double bars;
+                switch (request.Resolution)
+                {
+                    case Resolution.Daily:
+                        bars = tradableDays;
+                        break;
+                    case Resolution.Tick:
+                        // unknowable upfront: liquid symbols see ~10 trades and 100+ quotes per second,
+                        // so 10 data points per second of market time is still on the low side
+                        bars = tradableDays * request.ExchangeHours.RegularMarketDuration.TotalSeconds * AssumedTicksPerSecond;
+                        break;
+                    default:
+                        bars = tradableDays * (request.ExchangeHours.RegularMarketDuration / request.Resolution.ToTimeSpan());
+                        break;
+                }
+
+                // approximate data frame column counts per data point
+                var columns = request.TickType == TickType.Quote ? 10 : request.TickType == TickType.OpenInterest ? 1 : 5;
+                return (long)(bars * columns);
+            }
+        }
     }
 }

Common/IsolatorLimitResultProvider.cs

@@ -45,7 +45,7 @@ TimeMonitor timeMonitor
             }
 
             var timeProvider = RealTimeProvider.Instance;
-            isolatorLimitProvider.Consume(timeProvider, () => scheduledEvent.Scan(scanTimeUtc), timeMonitor);
+            isolatorLimitProvider.Consume(timeProvider, () => scheduledEvent.Scan(scanTimeUtc), timeMonitor, scheduledEvent.Name);
         }
 
         /// <summary>
@@ -63,13 +63,15 @@ public static void Consume(
             this IIsolatorLimitResultProvider isolatorLimitProvider,
             ITimeProvider timeProvider,
             Action code,
-            TimeMonitor timeMonitor
+            TimeMonitor timeMonitor,
+            string name = null
             )
         {
             var consumer = new TimeConsumer
             {
                 IsolatorLimitProvider = isolatorLimitProvider,
-                TimeProvider = timeProvider
+                TimeProvider = timeProvider,
+                Name = name
             };
             timeMonitor.Add(consumer);
             code();

Common/Scheduling/TimeConsumer.cs

@@ -42,5 +42,16 @@ public class TimeConsumer
         /// to be <see cref="IsolatorLimitProvider"/>
         /// </summary>
         public DateTime? NextTimeRequest { get; set; }
+
+        /// <summary>
+        /// Name of the work being executed, if any, e.g. the scheduled event's name. Used to name the
+        /// long-running work in logs when additional time is requested
+        /// </summary>
+        public string Name { get; set; }
+
+        /// <summary>
+        /// The number of additional minutes that have been requested for this consumer so far
+        /// </summary>
+        public int AdditionalMinutesRequested { get; set; }
     }
 }

Common/Scheduling/TimeMonitor.cs

@@ -16,6 +16,7 @@
 using System;
 using System.Threading;
 using QuantConnect.Util;
+using QuantConnect.Logging;
 using System.Collections.Generic;
 
 namespace QuantConnect.Scheduling
@@ -35,6 +36,12 @@ public class TimeMonitor : IDisposable
         /// in `IsolatorLimitResultProviderTests.cs</remarks>
         protected List<TimeConsumer> TimeConsumers { get; init; }
 
+        /// <summary>
+        /// Optional handler used to also surface long-running work warnings to the user,
+        /// e.g. through the result handler's debug messages. Engine logs alone don't reach the user's logs
+        /// </summary>
+        public Action<string> UserWarningHandler { get; set; }
+
         /// <summary>
         /// Returns the number of time consumers currently being monitored
         /// </summary>
@@ -107,6 +114,22 @@ protected virtual void ProcessConsumer(TimeConsumer consumer)
                 {
                     // pass
                 }
+
+                consumer.AdditionalMinutesRequested++;
+                if (consumer.Name != null)
+                {
+                    // name the long-running work: the first minute crossing is the actionable heads-up, later ones are informational
+                    var message = $"'{consumer.Name}' has been executing for over {consumer.AdditionalMinutesRequested} minute(s)";
+                    if (consumer.AdditionalMinutesRequested == 1)
+                    {
+                        Log.Error($"TimeMonitor.ProcessConsumer(): {message}. It will be stopped once the algorithm time loop limit is exhausted");
+                        UserWarningHandler?.Invoke($"Warning: {message}. It will be stopped once the algorithm time loop limit is exhausted");
+                    }
+                    else
+                    {
+                        Log.Trace($"TimeMonitor.ProcessConsumer(): {message}");
+                    }
+                }
             }
         }
 

Engine/AlgorithmManager.cs

@@ -101,7 +101,8 @@ public AlgorithmManager(bool liveMode, AlgorithmNodePacket job = null)
             // initialize the time limit manager
             TimeLimit = new AlgorithmTimeLimitManager(
                 CreateTokenBucket(job?.Controls?.TrainingLimits),
-                TimeSpan.FromMinutes(Config.GetDouble("algorithm-manager-time-loop-maximum", 20))
+                TimeSpan.FromMinutes(Config.GetDouble("algorithm-manager-time-loop-maximum", 20)),
+                TimeSpan.FromMinutes(Config.GetDouble("algorithm-manager-time-loop-warning", 3))
             );
         }
 
@@ -123,6 +124,8 @@ public void Run(AlgorithmNodePacket job, IAlgorithm algorithm, ISynchronizer syn
             //Initialize:
             _algorithm = algorithm;
             _performanceTrackingTool = performanceTrackingTool;
+            // surface time limit warnings in the user's logs, not just the engine log
+            TimeLimit.UserWarningHandler = results.DebugMessage;
 
             var token = cancellationTokenSource.Token;
             _cancellationTokenSource = cancellationTokenSource;

Engine/AlgorithmTimeLimitManager.cs

@@ -1,4 +1,4 @@
-/*
+/*
  * QUANTCONNECT.COM - Democratizing Finance, Empowering Individuals.
  * Lean Algorithmic Trading Engine v2.0. Copyright 2014 QuantConnect Corporation.
  *
@@ -35,13 +35,21 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider
 
         private volatile ReferenceWrapper<DateTime> _currentTimeStepTime;
         private readonly TimeSpan _timeLoopMaximum;
+        private readonly TimeSpan _timeLoopWarningThreshold;
+        private volatile bool _timeStepWarningSent;
 
         /// <summary>
         /// Gets the additional time bucket which is responsible for tracking additional time requested
         /// for processing via long-running scheduled events. In LEAN, we use the <see cref="LeakyBucket"/>
         /// </summary>
         public ITokenBucket AdditionalTimeBucket { get; }
 
+        /// <summary>
+        /// Optional handler used to also surface the slow time step warning to the user,
+        /// e.g. through the result handler's debug messages. Engine logs alone don't reach the user's logs
+        /// </summary>
+        public Action<string> UserWarningHandler { get; set; }
+
         /// <summary>
         /// Initializes a new instance of <see cref="AlgorithmTimeLimitManager"/> to manage the
         /// creation of <see cref="IsolatorLimitResult"/> instances as it pertains to the
@@ -52,9 +60,12 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider
         /// <param name="timeLoopMaximum">Specifies the maximum amount of time the algorithm is permitted to
         /// spend in a single time loop. This value can be overriden if certain actions are taken by the
         /// algorithm, such as invoking the training methods.</param>
-        public AlgorithmTimeLimitManager(ITokenBucket additionalTimeBucket, TimeSpan timeLoopMaximum)
+        /// <param name="timeLoopWarningThreshold">Elapsed time of a single time loop after which a warning is logged,
+        /// once per time step. Defaults to three minutes; a non positive value disables the warning</param>
+        public AlgorithmTimeLimitManager(ITokenBucket additionalTimeBucket, TimeSpan timeLoopMaximum, TimeSpan? timeLoopWarningThreshold = null)
         {
             _timeLoopMaximum = timeLoopMaximum;
+            _timeLoopWarningThreshold = timeLoopWarningThreshold ?? TimeSpan.FromMinutes(3);
             AdditionalTimeBucket = additionalTimeBucket;
             _currentTimeStepTime = new ReferenceWrapper<DateTime>(DateTime.MinValue);
         }
@@ -80,6 +91,7 @@ public void StartNewTimeStep()
             // accessing DateTime.UtcNow from the algorithm manager thread to the isolator thread
             _currentTimeStepTime = new ReferenceWrapper<DateTime>(DateTime.MinValue);
             Interlocked.Exchange(ref _additionalMinutes, 0L);
+            _timeStepWarningSent = false;
         }
 
         /// <summary>
@@ -99,6 +111,22 @@ public IsolatorLimitResult IsWithinLimit()
         {
             TimeSpan currentTimeStepElapsed;
             var message = IsOutOfTime(out currentTimeStepElapsed) ? GetErrorMessage(currentTimeStepElapsed) : string.Empty;
+
+            // warn early about an abnormally long time step: an isolator kill minutes later is opaque,
+            // the elapsed-time warning is actionable now
+            if (message.Length == 0 && !_stopped && !_timeStepWarningSent
+                && _timeLoopWarningThreshold > TimeSpan.Zero && currentTimeStepElapsed > _timeLoopWarningThreshold)
+            {
+                _timeStepWarningSent = true;
+                var warning = $"the current time step has been executing for {currentTimeStepElapsed.TotalMinutes.ToStringInvariant("0.0")} minutes" +
+                    $" and the algorithm will be stopped if it exceeds {_timeLoopMaximum.TotalMinutes.ToStringInvariant()} minutes." +
+                    " Common causes: a slow scheduled event (named in 'TimeMonitor' logs), large history() requests," +
+                    " heavy on_data work or an infinite loop.";
+                // override flood protection: the same text repeats for each slow time step and each occurrence matters
+                Log.Error($"AlgorithmTimeLimitManager.IsWithinLimit(): {warning}", overrideMessageFloodProtection: true);
+                UserWarningHandler?.Invoke($"Warning: {warning}");
+            }
+
             return new IsolatorLimitResult(currentTimeStepElapsed, message);
         }