From 86a1259aed6a57e506b1ecbd646079cde1df034d Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Tue, 11 Aug 2026 13:48:26 -0400 Subject: [PATCH 01/11] Report out of memory in ZipDataCacheProvider.Fetch honestly instead of as a corrupt zip --- Engine/DataFeeds/ZipDataCacheProvider.cs | 31 +++++++++- .../ZipDataCacheProviderTests.cs | 58 +++++++++++++++++++ 2 files changed, 88 insertions(+), 1 deletion(-) diff --git a/Engine/DataFeeds/ZipDataCacheProvider.cs b/Engine/DataFeeds/ZipDataCacheProvider.cs index ca7ce83a5dba..a15ffb57df0d 100644 --- a/Engine/DataFeeds/ZipDataCacheProvider.cs +++ b/Engine/DataFeeds/ZipDataCacheProvider.cs @@ -97,6 +97,7 @@ public Stream Fetch(string key) } catch (Exception exception) { + RethrowIfOutOfMemory(exception, filename, entryName); if (exception is ZipException || exception is ZlibException) { Log.Error("ZipDataCacheProvider.Fetch(): Corrupt zip file/entry: " + filename + "#" + entryName + " Error: " + exception); @@ -109,8 +110,14 @@ public Stream Fetch(string key) } catch (Exception err) { - Log.Error(err, "Inner try/catch"); stream?.DisposeSafely(); + if (err is OutOfMemoryException) + { + // let the memory diagnostic bubble up: returning a null stream here would just resurface + // as a confusing downstream failure while the process is dying anyway + throw; + } + Log.Error(err, "Inner try/catch"); return null; } } @@ -290,6 +297,7 @@ private Stream CacheAndCreateEntryStream(string filename, string entryName) { // don't leak the file stream! dataStream.DisposeSafely(); + RethrowIfOutOfMemory(exception, filename, entryName); if (exception is ZipException || exception is ZlibException) { Log.Error("ZipDataCacheProvider.Fetch(): Corrupt zip file/entry: " + filename + "#" + entryName + " Error: " + exception); @@ -412,6 +420,7 @@ private bool Cache(string filename, out CachedZipFile cachedZip) } catch (Exception exception) { + RethrowIfOutOfMemory(exception, filename, entryName: null); if (exception is ZipException || exception is ZlibException) { Log.Error("ZipDataCacheProvider.Fetch(): Corrupt zip file/entry: " + filename + " Error: " + exception); @@ -425,6 +434,26 @@ private bool Cache(string filename, out CachedZipFile cachedZip) return false; } + /// + /// Rethrows the given exception as an honest memory diagnostic if it is, or wraps, an . + /// Ionic wraps allocation failures while reading a zip into 'ZipException: Cannot read that as a ZipFile', which we would + /// otherwise log as a corrupt zip file and swallow, sending users down a data-integrity path when the process is actually + /// out of memory, usually due to too many subscriptions or too much data being requested + /// + private static void RethrowIfOutOfMemory(Exception exception, string filename, string entryName) + { + for (var inner = exception; inner != null; inner = inner.InnerException) + { + if (inner is OutOfMemoryException) + { + var entry = entryName != null ? "#" + entryName : string.Empty; + throw new OutOfMemoryException("ZipDataCacheProvider.Fetch(): ran out of memory reading " + filename + entry + + ". This indicates memory exhaustion, not a corrupt data file: reduce the number of subscriptions" + + " (e.g. narrow option universe filters) or the amount of data requested.", exception); + } + } + } + /// /// Type for storing zipfile in cache diff --git a/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs b/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs index 0bd1a79174c4..12f579a41f71 100644 --- a/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs +++ b/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs @@ -51,6 +51,35 @@ public void MultiThreadReadWriteTest() dataCacheProvider.Dispose(); } + [Test] + public void FetchRethrowsOutOfMemoryAsMemoryDiagnostic() + { + // Ionic wraps the allocation failure into ZipException("Cannot read that as a ZipFile"), which used to be + // logged as a corrupt zip file and swallowed, see A-abb25be1. We want an honest memory diagnostic instead. + using var dataCacheProvider = new ZipDataCacheProvider(new OutOfMemoryDataProvider()); + + var exception = Assert.Throws( + () => dataCacheProvider.Fetch("/data/option/usa/daily/pep_2026_trade_american.zip#entry.csv")); + + StringAssert.Contains("ran out of memory", exception.Message); + StringAssert.DoesNotContain("Corrupt zip", exception.Message); + Assert.IsNotNull(exception.InnerException); + } + + [Test] + public void FetchDoesNotThrowOnCorruptZipFile() + { + // a truly corrupt file must keep the previous behavior: log and return null instead of throwing + using var dataCacheProvider = new ZipDataCacheProvider(TestGlobals.DataProvider, cacheTimer: 0.1); + + var tempZipFile = Path.GetTempFileName().Replace(".tmp", ".zip", StringComparison.InvariantCulture); + File.WriteAllText(tempZipFile, "corrupted zip"); + + Stream result = null; + Assert.DoesNotThrow(() => result = dataCacheProvider.Fetch(tempZipFile + "#testEntry.csv")); + Assert.IsNull(result); + } + [Test] public void StoreFailsCorruptedFile() { @@ -72,5 +101,34 @@ private void ReadAndWrite(IDataCacheProvider dataCacheProvider, byte[] data) dataCacheProvider.Fetch(_tempZipFileEntry); dataCacheProvider.Store(_tempZipFileEntry, data); } + + /// + /// Provider whose streams fail allocation-style, simulating reading a zip while the process is out of memory + /// + private class OutOfMemoryDataProvider : IDataProvider + { + public event EventHandler NewDataRequest; + + public Stream Fetch(string key) + { + NewDataRequest?.Invoke(this, null); + return new OutOfMemoryStream(); + } + + private class OutOfMemoryStream : Stream + { + public override bool CanRead => true; + public override bool CanSeek => true; + public override bool CanWrite => false; + public override long Length => 1024; + public override long Position { get; set; } + + public override void Flush() { } + public override int Read(byte[] buffer, int offset, int count) => throw new OutOfMemoryException(); + public override long Seek(long offset, SeekOrigin origin) => Position; + public override void SetLength(long value) => throw new NotSupportedException(); + public override void Write(byte[] buffer, int offset, int count) => throw new NotSupportedException(); + } + } } } From b86f0a1736a6da472f47594981da7c2a3045c2d7 Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Tue, 11 Aug 2026 13:48:26 -0400 Subject: [PATCH 02/11] Warn on large and repeatedly overlapping history requests --- Algorithm/QCAlgorithm.History.cs | 105 ++++++++++++++++++++++- Tests/Algorithm/AlgorithmHistoryTests.cs | 74 ++++++++++++++++ 2 files changed, 178 insertions(+), 1 deletion(-) diff --git a/Algorithm/QCAlgorithm.History.cs b/Algorithm/QCAlgorithm.History.cs index 077b4cbda32f..e3556161626a 100644 --- a/Algorithm/QCAlgorithm.History.cs +++ b/Algorithm/QCAlgorithm.History.cs @@ -38,6 +38,20 @@ public partial class QCAlgorithm private bool _dataDictionaryTickWarningSent; + // Large history request diagnostics: huge or repeatedly re-fetched requests are a recurring cause of + // multi-hour stalls and out of memory kills, warn upfront instead of failing with an opaque error later. + // A single request over the cells threshold triggers the size warning; requests over threshold divided by + // 'OverlappingRequestSizeDivisor' are tracked for the "re-fetch an overlapping window every day/selection" + // pattern, warning after 'OverlappingRequestsWarningCount' consecutive overlapping calls + private const int OverlappingRequestsWarningCount = 30; + private const int OverlappingRequestSizeDivisor = 50; + private readonly long _historyRequestCellsWarningThreshold = Config.GetInt("history-request-cells-warning-threshold", 5000000); + private bool _largeHistoryRequestWarningSent; + private bool _overlappingHistoryRequestsWarningSent; + private int _consecutiveOverlappingHistoryRequests; + private DateTime _previousLargeHistoryRequestStartUtc; + private DateTime _previousLargeHistoryRequestEndUtc; + /// /// Gets or sets the history provider for the algorithm /// @@ -1019,7 +1033,9 @@ protected IEnumerable> GetDataTypedHistory(IEnumerable History(IEnumerable requests, DateTimeZone timeZone) { // filter out any universe securities that may have made it this far - var filteredRequests = GetFilterestRequests(requests); + var filteredRequests = GetFilterestRequests(requests).ToList(); + + WarnOnLargeHistoryRequests(filteredRequests); // filter out future data to prevent look ahead bias var history = HistoryProvider.GetHistory(filteredRequests, timeZone); @@ -1035,6 +1051,93 @@ private IEnumerable History(IEnumerable requests, DateTim return history; } + /// + /// Emits one-time warnings for history requests that are likely to stall the algorithm or run it out of memory: + /// a single call estimated over data cells (bars x columns), + /// and repeated calls with time windows overlapping the previous call, e.g. re-fetching a long lookback on + /// every day or universe selection instead of updating incrementally + /// + private void WarnOnLargeHistoryRequests(List requests) + { + if (_largeHistoryRequestWarningSent && _overlappingHistoryRequestsWarningSent || 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 (!_largeHistoryRequestWarningSent && estimatedCells >= _historyRequestCellsWarningThreshold) + { + _largeHistoryRequestWarningSent = true; + Debug($"Warning: large history request, estimated at ~{estimatedCells.ToStringInvariant("N0")} data cells" + + $" across {requests.Count} request(s). Large history calls are slow and can run the algorithm out of memory:" + + " consider requesting fewer symbols, a shorter period or a coarser resolution."); + } + + if (!_overlappingHistoryRequestsWarningSent && estimatedCells >= _historyRequestCellsWarningThreshold / OverlappingRequestSizeDivisor) + { + var overlaps = startUtc < _previousLargeHistoryRequestEndUtc && endUtc > _previousLargeHistoryRequestStartUtc; + _consecutiveOverlappingHistoryRequests = overlaps ? _consecutiveOverlappingHistoryRequests + 1 : 0; + _previousLargeHistoryRequestStartUtc = startUtc; + _previousLargeHistoryRequestEndUtc = endUtc; + + if (_consecutiveOverlappingHistoryRequests >= OverlappingRequestsWarningCount) + { + _overlappingHistoryRequestsWarningSent = true; + Debug($"Warning: history() has been called {OverlappingRequestsWarningCount}+ times with time windows overlapping" + + " the previous call. Re-fetching a long lookback repeatedly is slow: consider fetching history once and keeping" + + " it updated with a rolling window, consolidators or indicator warm up, or shortening the lookback."); + } + } + } + + /// + /// Rough order-of-magnitude estimate of the data cells (bars x columns) a history request will produce + /// + 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, use a conservative 1 data point per second of market time + bars = tradableDays * request.ExchangeHours.RegularMarketDuration.TotalSeconds; + 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); + } + private IEnumerable GetFilterestRequests(IEnumerable requests) { var sentMessage = false; diff --git a/Tests/Algorithm/AlgorithmHistoryTests.cs b/Tests/Algorithm/AlgorithmHistoryTests.cs index e6c615377946..3fb18b916dcf 100644 --- a/Tests/Algorithm/AlgorithmHistoryTests.cs +++ b/Tests/Algorithm/AlgorithmHistoryTests.cs @@ -38,6 +38,7 @@ using QuantConnect.Data.UniverseSelection; using QuantConnect.Tests.Common.Data.Fundamental; using QuantConnect.Logging; +using QuantConnect.Configuration; namespace QuantConnect.Tests.Algorithm { @@ -4287,6 +4288,79 @@ private static TestCaseData[] GetHistoryWithDataNormalizationModeTestCases() }).ToArray(); } + [Test] + public void WarnsOnLargeHistoryRequest() + { + Config.Set("history-request-cells-warning-threshold", "1000"); + try + { + var algorithm = CreateAlgorithmForHistoryWarningTests(); + var symbol = algorithm.AddEquity("SPY", Resolution.Daily).Symbol; + + // ~365 daily bars x 5 columns > 1000 cells + algorithm.History(new[] { symbol }, 365, Resolution.Daily); + + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("large history request"))); + + // the warning is only sent once per algorithm + algorithm.History(new[] { symbol }, 365, Resolution.Daily); + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("large history request"))); + } + finally + { + Config.Reset(); + } + } + + [Test] + public void DoesNotWarnOnSmallHistoryRequest() + { + // default threshold + var algorithm = CreateAlgorithmForHistoryWarningTests(); + var symbol = algorithm.AddEquity("SPY", Resolution.Daily).Symbol; + + algorithm.History(new[] { symbol }, 30, Resolution.Daily); + + Assert.AreEqual(0, algorithm.DebugMessages.Count(x => x.Contains("large history request"))); + } + + [Test] + public void WarnsOnRepeatedOverlappingHistoryRequests() + { + // the "large call" floor tracked for overlap detection is threshold / 50 = 2000 cells + Config.Set("history-request-cells-warning-threshold", "100000"); + try + { + var algorithm = CreateAlgorithmForHistoryWarningTests(); + var symbol = algorithm.AddEquity("SPY", Resolution.Daily).Symbol; + + for (var i = 0; i < 40; i++) + { + // ~800 daily bars x 5 columns = ~4000 cells: over the large-call floor, under the size warning threshold + algorithm.History(new[] { symbol }, 800, Resolution.Daily); + } + + Assert.AreEqual(0, algorithm.DebugMessages.Count(x => x.Contains("large history request"))); + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("overlapping"))); + } + finally + { + Config.Reset(); + } + } + + private static QCAlgorithm CreateAlgorithmForHistoryWarningTests() + { + // the warning thresholds are read from the config when the algorithm is created, + // so we create a dedicated instance instead of using the fixture's algorithm + var algorithm = new QCAlgorithm(); + algorithm.SubscriptionManager.SetDataManager(new DataManagerStub(algorithm)); + algorithm.HistoryProvider = new TestHistoryProvider(); + algorithm.SetStartDate(2013, 10, 07); + algorithm.Settings.SeedInitialPrices = false; + return algorithm; + } + private QCAlgorithm GetAlgorithm(DateTime dateTime) { var algorithm = new QCAlgorithm(); From aa33bdcb240fffeed8602c58e0bf202446394441 Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Tue, 11 Aug 2026 13:48:26 -0400 Subject: [PATCH 03/11] Warn early on slow time steps, naming running scheduled events --- Common/IsolatorLimitResultProvider.cs | 8 ++- Common/Scheduling/TimeConsumer.cs | 11 +++ Common/Scheduling/TimeMonitor.cs | 17 +++++ Engine/AlgorithmManager.cs | 3 +- Engine/AlgorithmTimeLimitManager.cs | 26 ++++++- .../IsolatorLimitResultProviderTests.cs | 38 ++++++++++ .../Engine/AlgorithmTimeLimitManagerTests.cs | 71 +++++++++++++++++++ 7 files changed, 169 insertions(+), 5 deletions(-) diff --git a/Common/IsolatorLimitResultProvider.cs b/Common/IsolatorLimitResultProvider.cs index 5bf7d47b5f89..d19ecf273774 100644 --- a/Common/IsolatorLimitResultProvider.cs +++ b/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); } /// @@ -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(); diff --git a/Common/Scheduling/TimeConsumer.cs b/Common/Scheduling/TimeConsumer.cs index 0ddf9a2e82bb..6936165a8f20 100644 --- a/Common/Scheduling/TimeConsumer.cs +++ b/Common/Scheduling/TimeConsumer.cs @@ -42,5 +42,16 @@ public class TimeConsumer /// to be /// public DateTime? NextTimeRequest { get; set; } + + /// + /// 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 + /// + public string Name { get; set; } + + /// + /// The number of additional minutes that have been requested for this consumer so far + /// + public int AdditionalMinutesRequested { get; set; } } } diff --git a/Common/Scheduling/TimeMonitor.cs b/Common/Scheduling/TimeMonitor.cs index b302257d6c94..e47d1e91b9e4 100644 --- a/Common/Scheduling/TimeMonitor.cs +++ b/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 @@ -107,6 +108,22 @@ protected virtual void ProcessConsumer(TimeConsumer consumer) { // pass } + + consumer.AdditionalMinutesRequested++; + if (consumer.Name != null) + { + // name the long-running work upfront: an opaque isolator kill minutes later is much harder to act on. + // The first crossing of the one minute mark is the actionable heads-up, following ones are informational + var message = $"TimeMonitor.ProcessConsumer(): '{consumer.Name}' has been executing for over {consumer.AdditionalMinutesRequested} minute(s)"; + if (consumer.AdditionalMinutesRequested == 1) + { + Log.Error($"{message}. It will be stopped once the algorithm time loop limit is exhausted"); + } + else + { + Log.Trace(message); + } + } } } diff --git a/Engine/AlgorithmManager.cs b/Engine/AlgorithmManager.cs index 9bfd29cafdba..1bbbc6cb521e 100644 --- a/Engine/AlgorithmManager.cs +++ b/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", 1)) ); } diff --git a/Engine/AlgorithmTimeLimitManager.cs b/Engine/AlgorithmTimeLimitManager.cs index e564ad5a75af..03ac2bd56a5b 100644 --- a/Engine/AlgorithmTimeLimitManager.cs +++ b/Engine/AlgorithmTimeLimitManager.cs @@ -35,6 +35,8 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider private volatile ReferenceWrapper _currentTimeStepTime; private readonly TimeSpan _timeLoopMaximum; + private readonly TimeSpan _timeLoopWarningThreshold; + private volatile bool _timeStepWarningSent; /// /// Gets the additional time bucket which is responsible for tracking additional time requested @@ -52,9 +54,13 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider /// 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. - public AlgorithmTimeLimitManager(ITokenBucket additionalTimeBucket, TimeSpan timeLoopMaximum) + /// Elapsed time of a single time loop after which a warning is + /// logged, once per time step, so a slow handler is flagged well before the time loop maximum stops the + /// algorithm. Defaults to one minute; a non positive value disables the warning + public AlgorithmTimeLimitManager(ITokenBucket additionalTimeBucket, TimeSpan timeLoopMaximum, TimeSpan? timeLoopWarningThreshold = null) { _timeLoopMaximum = timeLoopMaximum; + _timeLoopWarningThreshold = timeLoopWarningThreshold ?? TimeSpan.FromMinutes(1); AdditionalTimeBucket = additionalTimeBucket; _currentTimeStepTime = new ReferenceWrapper(DateTime.MinValue); } @@ -80,6 +86,7 @@ public void StartNewTimeStep() // accessing DateTime.UtcNow from the algorithm manager thread to the isolator thread _currentTimeStepTime = new ReferenceWrapper(DateTime.MinValue); Interlocked.Exchange(ref _additionalMinutes, 0L); + _timeStepWarningSent = false; } /// @@ -99,6 +106,23 @@ public IsolatorLimitResult IsWithinLimit() { TimeSpan currentTimeStepElapsed; var message = IsOutOfTime(out currentTimeStepElapsed) ? GetErrorMessage(currentTimeStepElapsed) : string.Empty; + + // warn early about an abnormally long time step: waiting for the time loop maximum to stop the algorithm + // costs many opaque minutes, while a warning naming the elapsed time is immediately actionable + if (message.Length == 0 && !_stopped && !_timeStepWarningSent + && _timeLoopWarningThreshold > TimeSpan.Zero && currentTimeStepElapsed > _timeLoopWarningThreshold) + { + _timeStepWarningSent = true; + // override message flood protection: the message text repeats for every slow time step (at most one + // line per warning threshold of wall-clock time) and each occurrence is relevant + Log.Error("AlgorithmTimeLimitManager.IsWithinLimit(): " + + $"the current algorithm time step has been executing for {currentTimeStepElapsed.TotalMinutes.ToStringInvariant("0.0")} minutes; " + + $"the algorithm will be stopped if a single time step exceeds {_timeLoopMaximum.TotalMinutes.ToStringInvariant()} minutes. " + + "If a scheduled event is running it is named in a 'TimeMonitor' log entry; other common causes are large" + + " history() requests, heavy work in data event handlers (e.g. on_data) or an infinite loop.", + overrideMessageFloodProtection: true); + } + return new IsolatorLimitResult(currentTimeStepElapsed, message); } diff --git a/Tests/Common/IsolatorLimitResultProviderTests.cs b/Tests/Common/IsolatorLimitResultProviderTests.cs index 8dea41832a28..14e554c70c73 100644 --- a/Tests/Common/IsolatorLimitResultProviderTests.cs +++ b/Tests/Common/IsolatorLimitResultProviderTests.cs @@ -20,6 +20,7 @@ using System.Threading.Tasks; using NUnit.Framework; using QuantConnect.Lean.Engine.DataFeeds; +using QuantConnect.Logging; using QuantConnect.Scheduling; using QuantConnect.Util; @@ -144,6 +145,43 @@ public void ConsumesMultipleMinutes() Assert.AreEqual(0, _timeMonitor.Count); } + [Test] + public void ConsumeNamesTheWorkWhenRequestingAdditionalTime() + { + var previousLogHandler = Log.LogHandler; + try + { + var logHandler = new QueueLogHandler(); + Log.LogHandler = logHandler; + + var timeProvider = new ManualTimeProvider(new DateTime(2000, 01, 01)); + var provider = new FakeIsolatorLimitResultProvider(); + + Action code = () => + { + // lets give the monitor time to register the initial time + _timeMonitorEvent.WaitOne(); + timeProvider.Advance(TimeSpan.FromSeconds(65)); + // give the monitoring task time to request more time + _timeMonitorEvent.WaitOne(); + }; + + provider.Consume(timeProvider, code, _timeMonitor, "My Slow Scheduled Event"); + + Assert.AreEqual(1, provider.Invocations.Count); + Assert.AreEqual(1, logHandler.Logs.Count( + entry => entry.Message.Contains("'My Slow Scheduled Event' has been executing for over 1 minute"))); + + // give time to the monitor to register the time consumer ended + _timeMonitorEvent.WaitOne(); + Assert.AreEqual(0, _timeMonitor.Count); + } + finally + { + Log.LogHandler = previousLogHandler; + } + } + private class FakeIsolatorLimitResultProvider : IIsolatorLimitResultProvider { private List _ivocations = new List(); diff --git a/Tests/Engine/AlgorithmTimeLimitManagerTests.cs b/Tests/Engine/AlgorithmTimeLimitManagerTests.cs index 580aa1b76646..16c501327b7c 100644 --- a/Tests/Engine/AlgorithmTimeLimitManagerTests.cs +++ b/Tests/Engine/AlgorithmTimeLimitManagerTests.cs @@ -16,11 +16,14 @@ using System; using System.Collections.Generic; +using System.Linq; +using System.Threading; using System.Threading.Tasks; using NUnit.Framework; using QuantConnect.Algorithm.CSharp; using QuantConnect.Configuration; using QuantConnect.Lean.Engine; +using QuantConnect.Logging; using QuantConnect.Util.RateLimit; namespace QuantConnect.Tests.Engine @@ -57,6 +60,74 @@ public void StopsAlgorithm() parameter.ExpectedFinalStatus); } + [Test] + public void WarnsOnceOnLongTimeStepWithoutFailing() + { + var previousLogHandler = Log.LogHandler; + try + { + var logHandler = new QueueLogHandler(); + Log.LogHandler = logHandler; + + var timeManager = new AlgorithmTimeLimitManager(TokenBucket.Null, TimeSpan.FromMinutes(20), + timeLoopWarningThreshold: TimeSpan.FromMilliseconds(5)); + timeManager.StartNewTimeStep(); + // the first call initializes the current time step start time + Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); + Thread.Sleep(50); + + // the time step is over the warning threshold: it warns but does not fail + var result = timeManager.IsWithinLimit(); + Assert.IsTrue(result.IsWithinCustomLimits, result.ErrorMessage); + Assert.AreEqual(1, WarningCount(logHandler)); + + // only warns once per time step + Thread.Sleep(20); + Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); + Assert.AreEqual(1, WarningCount(logHandler)); + + // a new slow time step warns again + timeManager.StartNewTimeStep(); + Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); + Thread.Sleep(50); + Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); + Assert.AreEqual(2, WarningCount(logHandler)); + } + finally + { + Log.LogHandler = previousLogHandler; + } + } + + [Test] + public void DoesNotWarnOnFastTimeStep() + { + var previousLogHandler = Log.LogHandler; + try + { + var logHandler = new QueueLogHandler(); + Log.LogHandler = logHandler; + + // default one minute warning threshold + var timeManager = new AlgorithmTimeLimitManager(TokenBucket.Null, TimeSpan.FromMinutes(20)); + timeManager.StartNewTimeStep(); + Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); + Thread.Sleep(20); + Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); + + Assert.AreEqual(0, WarningCount(logHandler)); + } + finally + { + Log.LogHandler = previousLogHandler; + } + } + + private static int WarningCount(QueueLogHandler logHandler) + { + return logHandler.Logs.Count(entry => entry.Message.Contains("time step has been executing")); + } + [Test] public void RaceCondition() { From 4147c66e981362d0cf7de7bb3d2d9b336a3c4478 Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Tue, 11 Aug 2026 13:48:26 -0400 Subject: [PATCH 04/11] Warn on large option universe selections --- Engine/DataFeeds/UniverseSelection.cs | 54 +++++++++++++++++++ .../DataFeeds/UniverseSelectionTests.cs | 51 ++++++++++++++++++ 2 files changed, 105 insertions(+) diff --git a/Engine/DataFeeds/UniverseSelection.cs b/Engine/DataFeeds/UniverseSelection.cs index e5512ba46122..aba2918b6506 100644 --- a/Engine/DataFeeds/UniverseSelection.cs +++ b/Engine/DataFeeds/UniverseSelection.cs @@ -17,6 +17,7 @@ using System.Collections.Generic; using System.Linq; using QuantConnect.Benchmarks; +using QuantConnect.Configuration; using QuantConnect.Data; using QuantConnect.Data.UniverseSelection; using QuantConnect.Interfaces; @@ -42,6 +43,8 @@ public class UniverseSelection private bool _initializedSecurityBenchmark; private bool _anyDoesNotHaveFundamentalDataWarningLogged; private readonly SecurityChangesConstructor _securityChangesConstructor; + private bool _optionUniverseSelectionSizeWarningSent; + private readonly int _optionUniverseContractsWarningThreshold = Config.GetInt("option-universe-contracts-warning-threshold", 500); /// /// Initializes a new instance of the class @@ -183,6 +186,11 @@ public SecurityChanges ApplyUniverseSelection(Universe universe, DateTime dateTi { // materialize the enumerable into a set for processing universe.Selected = selectSymbolsResult.ToHashSet(); + + if (universe is OptionChainUniverse optionChainUniverse) + { + WarnOnLargeOptionUniverseSelection(optionChainUniverse); + } } // first check for no pending removals, even if the universe selection @@ -473,6 +481,52 @@ public SecurityChanges HandleDelisting(BaseData data, bool isInternalFeed) return SecurityChanges.None; } + /// + /// Warns, once per algorithm, when option universe selections accumulate contracts beyond + /// 'option-universe-contracts-warning-threshold'. Every selected contract materializes into data subscriptions, + /// and wide filters, or many chained per-underlying option universes, are a recurring cause of out of memory + /// kills and multi-hour stalls. Warn only, never fail: the run may still succeed + /// + internal void WarnOnLargeOptionUniverseSelection(OptionChainUniverse universe) + { + if (_optionUniverseSelectionSizeWarningSent || _optionUniverseContractsWarningThreshold <= 0) + { + return; + } + + // aggregate over all option universes: many chained per-underlying chains are as heavy as a single wide one. + // Note that 'Selected' includes the prepended underlying symbol, which is not a contract + var totalContracts = 0; + var universeCount = 0; + foreach (var kvp in _algorithm.UniverseManager) + { + if (kvp.Value is OptionChainUniverse optionUniverse && optionUniverse.Selected != null) + { + totalContracts += Math.Max(0, optionUniverse.Selected.Count - 1); + universeCount++; + } + } + if (universeCount == 0) + { + // not registered in the universe manager, count the given universe only + universeCount = 1; + totalContracts = Math.Max(0, universe.Selected.Count - 1); + } + + if (totalContracts < _optionUniverseContractsWarningThreshold) + { + return; + } + + _optionUniverseSelectionSizeWarningSent = true; + var latestCount = Math.Max(0, universe.Selected.Count - 1); + _algorithm.Debug($"Warning: option universe selections have reached ~{totalContracts} contracts across {universeCount}" + + $" option universe(s), latest: {latestCount} contracts for {universe.Option.Symbol.Underlying.Value}. Each selected" + + " contract adds data subscriptions, which can slow down the algorithm and run it out of memory. Consider narrowing" + + " the universe filter (SetFilter/set_filter strikes and expiration ranges) or trading specific contracts found via" + + " OptionChain()/option_chain() and added with AddOptionContract/add_option_contract."); + } + private void RemoveSecurityFromUniverse( List removedMembers, DateTime dateTimeUtc, diff --git a/Tests/Engine/DataFeeds/UniverseSelectionTests.cs b/Tests/Engine/DataFeeds/UniverseSelectionTests.cs index 5f2e47d43625..607df5f6a9ff 100644 --- a/Tests/Engine/DataFeeds/UniverseSelectionTests.cs +++ b/Tests/Engine/DataFeeds/UniverseSelectionTests.cs @@ -18,6 +18,7 @@ using System.Linq; using Moq; using NUnit.Framework; +using QuantConnect.Configuration; using QuantConnect.Data; using QuantConnect.Data.Fundamental; using QuantConnect.Data.UniverseSelection; @@ -33,6 +34,56 @@ namespace QuantConnect.Tests.Engine.DataFeeds [TestFixture] public class UniverseSelectionTests { + [Test] + public void WarnsOnLargeOptionUniverseSelection() + { + Config.Set("option-universe-contracts-warning-threshold", "10"); + try + { + var algorithm = new AlgorithmStub(new MockDataFeed()); + algorithm.SetStartDate(2014, 6, 6); + var option = algorithm.AddOption("AAPL"); + // OnEndOfTimeStep will add all pending universe additions + algorithm.OnEndOfTimeStep(); + var universe = algorithm.UniverseManager.Values.OfType().Single(); + + // below the threshold: no warning + universe.Selected = CreateOptionSelection(option.Symbol.Underlying, 5); + algorithm.DataManager.UniverseSelection.WarnOnLargeOptionUniverseSelection(universe); + Assert.AreEqual(0, OptionUniverseWarningCount(algorithm)); + + // above the threshold: warns + universe.Selected = CreateOptionSelection(option.Symbol.Underlying, 15); + algorithm.DataManager.UniverseSelection.WarnOnLargeOptionUniverseSelection(universe); + Assert.AreEqual(1, OptionUniverseWarningCount(algorithm)); + + // only warns once per algorithm + algorithm.DataManager.UniverseSelection.WarnOnLargeOptionUniverseSelection(universe); + Assert.AreEqual(1, OptionUniverseWarningCount(algorithm)); + } + finally + { + Config.Reset(); + } + } + + private static int OptionUniverseWarningCount(AlgorithmStub algorithm) + { + return algorithm.DebugMessages.Count(x => x.Contains("option universe selections")); + } + + private static HashSet CreateOptionSelection(Symbol underlying, int contractCount) + { + // option universe selections have the underlying symbol prepended + var selected = new HashSet { underlying }; + var expiry = new DateTime(2014, 7, 19); + for (var i = 0; i < contractCount; i++) + { + selected.Add(Symbol.CreateOption(underlying, Market.USA, OptionStyle.American, OptionRight.Call, 100 + i, expiry)); + } + return selected; + } + [Test] public void CreatedEquityIsNotAddedToSymbolCache() { From ed815bffdaf46e8628852a976a07015416b8900f Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Wed, 12 Aug 2026 12:41:22 -0400 Subject: [PATCH 05/11] Group history request diagnostics into a nested helper class Moves the large/overlapping history request warning state and logic out of the QCAlgorithm partial into a private LargeHistoryRequestDiagnostics nested class with a single entry point, keeping the algorithm class surface small. No behavior change. --- Algorithm/QCAlgorithm.History.cs | 210 ++++++++++++++++--------------- 1 file changed, 109 insertions(+), 101 deletions(-) diff --git a/Algorithm/QCAlgorithm.History.cs b/Algorithm/QCAlgorithm.History.cs index e3556161626a..2863e927c970 100644 --- a/Algorithm/QCAlgorithm.History.cs +++ b/Algorithm/QCAlgorithm.History.cs @@ -38,19 +38,7 @@ public partial class QCAlgorithm private bool _dataDictionaryTickWarningSent; - // Large history request diagnostics: huge or repeatedly re-fetched requests are a recurring cause of - // multi-hour stalls and out of memory kills, warn upfront instead of failing with an opaque error later. - // A single request over the cells threshold triggers the size warning; requests over threshold divided by - // 'OverlappingRequestSizeDivisor' are tracked for the "re-fetch an overlapping window every day/selection" - // pattern, warning after 'OverlappingRequestsWarningCount' consecutive overlapping calls - private const int OverlappingRequestsWarningCount = 30; - private const int OverlappingRequestSizeDivisor = 50; - private readonly long _historyRequestCellsWarningThreshold = Config.GetInt("history-request-cells-warning-threshold", 5000000); - private bool _largeHistoryRequestWarningSent; - private bool _overlappingHistoryRequestsWarningSent; - private int _consecutiveOverlappingHistoryRequests; - private DateTime _previousLargeHistoryRequestStartUtc; - private DateTime _previousLargeHistoryRequestEndUtc; + private readonly LargeHistoryRequestDiagnostics _largeHistoryRequestDiagnostics = new(); /// /// Gets or sets the history provider for the algorithm @@ -1035,7 +1023,7 @@ private IEnumerable History(IEnumerable requests, DateTim // filter out any universe securities that may have made it this far var filteredRequests = GetFilterestRequests(requests).ToList(); - WarnOnLargeHistoryRequests(filteredRequests); + _largeHistoryRequestDiagnostics.WarnOnLargeHistoryRequests(filteredRequests, Debug); // filter out future data to prevent look ahead bias var history = HistoryProvider.GetHistory(filteredRequests, timeZone); @@ -1051,93 +1039,6 @@ private IEnumerable History(IEnumerable requests, DateTim return history; } - /// - /// Emits one-time warnings for history requests that are likely to stall the algorithm or run it out of memory: - /// a single call estimated over data cells (bars x columns), - /// and repeated calls with time windows overlapping the previous call, e.g. re-fetching a long lookback on - /// every day or universe selection instead of updating incrementally - /// - private void WarnOnLargeHistoryRequests(List requests) - { - if (_largeHistoryRequestWarningSent && _overlappingHistoryRequestsWarningSent || 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 (!_largeHistoryRequestWarningSent && estimatedCells >= _historyRequestCellsWarningThreshold) - { - _largeHistoryRequestWarningSent = true; - Debug($"Warning: large history request, estimated at ~{estimatedCells.ToStringInvariant("N0")} data cells" + - $" across {requests.Count} request(s). Large history calls are slow and can run the algorithm out of memory:" + - " consider requesting fewer symbols, a shorter period or a coarser resolution."); - } - - if (!_overlappingHistoryRequestsWarningSent && estimatedCells >= _historyRequestCellsWarningThreshold / OverlappingRequestSizeDivisor) - { - var overlaps = startUtc < _previousLargeHistoryRequestEndUtc && endUtc > _previousLargeHistoryRequestStartUtc; - _consecutiveOverlappingHistoryRequests = overlaps ? _consecutiveOverlappingHistoryRequests + 1 : 0; - _previousLargeHistoryRequestStartUtc = startUtc; - _previousLargeHistoryRequestEndUtc = endUtc; - - if (_consecutiveOverlappingHistoryRequests >= OverlappingRequestsWarningCount) - { - _overlappingHistoryRequestsWarningSent = true; - Debug($"Warning: history() has been called {OverlappingRequestsWarningCount}+ times with time windows overlapping" + - " the previous call. Re-fetching a long lookback repeatedly is slow: consider fetching history once and keeping" + - " it updated with a rolling window, consolidators or indicator warm up, or shortening the lookback."); - } - } - } - - /// - /// Rough order-of-magnitude estimate of the data cells (bars x columns) a history request will produce - /// - 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, use a conservative 1 data point per second of market time - bars = tradableDays * request.ExchangeHours.RegularMarketDuration.TotalSeconds; - 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); - } - private IEnumerable GetFilterestRequests(IEnumerable requests) { var sentMessage = false; @@ -1658,5 +1559,112 @@ private static IEnumerable WrapPythonDataHistory(IEnumerable histo } } } + + /// + /// Large history request diagnostics: huge or repeatedly re-fetched requests are a recurring cause of + /// multi-hour stalls and out of memory kills, warn upfront instead of failing with an opaque error later. + /// A single call over the cells threshold triggers the size warning; calls over threshold divided by + /// are tracked for the "re-fetch an overlapping window every + /// day/selection" pattern, warning after consecutive overlapping calls + /// + private sealed class LargeHistoryRequestDiagnostics + { + private const int OverlappingRequestsWarningCount = 30; + private const int OverlappingRequestSizeDivisor = 50; + + 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; + + /// + /// Emits one-time warnings for history requests that are likely to stall the algorithm or run it out of memory: + /// a single call estimated over data cells (bars x columns), + /// and repeated calls with time windows overlapping the previous call, e.g. re-fetching a long lookback on + /// every day or universe selection instead of updating incrementally + /// + public void WarnOnLargeHistoryRequests(List requests, Action debug) + { + 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). Large history calls are slow and can run the algorithm out of memory:" + + " consider requesting 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}+ times with time windows overlapping" + + " the previous call. Re-fetching a long lookback repeatedly is slow: consider fetching history once and keeping" + + " it updated with a rolling window, consolidators or indicator warm up, or shortening the lookback."); + } + } + } + + /// + /// Rough order-of-magnitude estimate of the data cells (bars x columns) a history request will produce + /// + 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, use a conservative 1 data point per second of market time + bars = tradableDays * request.ExchangeHours.RegularMarketDuration.TotalSeconds; + 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); + } + } } } From a987f82eb45655af99755c6bb1f687e075436032 Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Wed, 12 Aug 2026 13:54:58 -0400 Subject: [PATCH 06/11] Tighten guardrail warning messages and comments Keep the new user-facing warnings and code comments short and direct so they are easy to act on. No behavior change. --- Algorithm/QCAlgorithm.History.cs | 23 +++++++++-------------- Common/Scheduling/TimeMonitor.cs | 3 +-- Engine/AlgorithmTimeLimitManager.cs | 22 ++++++++++------------ Engine/DataFeeds/UniverseSelection.cs | 18 ++++++++---------- Engine/DataFeeds/ZipDataCacheProvider.cs | 12 +++++------- 5 files changed, 33 insertions(+), 45 deletions(-) diff --git a/Algorithm/QCAlgorithm.History.cs b/Algorithm/QCAlgorithm.History.cs index 2863e927c970..04059547dc86 100644 --- a/Algorithm/QCAlgorithm.History.cs +++ b/Algorithm/QCAlgorithm.History.cs @@ -1561,11 +1561,9 @@ private static IEnumerable WrapPythonDataHistory(IEnumerable histo } /// - /// Large history request diagnostics: huge or repeatedly re-fetched requests are a recurring cause of - /// multi-hour stalls and out of memory kills, warn upfront instead of failing with an opaque error later. - /// A single call over the cells threshold triggers the size warning; calls over threshold divided by - /// are tracked for the "re-fetch an overlapping window every - /// day/selection" pattern, warning after consecutive overlapping calls + /// 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 /// private sealed class LargeHistoryRequestDiagnostics { @@ -1580,10 +1578,7 @@ private sealed class LargeHistoryRequestDiagnostics private DateTime _previousRequestEndUtc; /// - /// Emits one-time warnings for history requests that are likely to stall the algorithm or run it out of memory: - /// a single call estimated over data cells (bars x columns), - /// and repeated calls with time windows overlapping the previous call, e.g. re-fetching a long lookback on - /// every day or universe selection instead of updating incrementally + /// Checks the given requests and emits the applicable warnings through the given debug callback /// public void WarnOnLargeHistoryRequests(List requests, Action debug) { @@ -1612,8 +1607,8 @@ public void WarnOnLargeHistoryRequests(List requests, Action= _cellsWarningThreshold / OverlappingRequestSizeDivisor) @@ -1626,9 +1621,9 @@ public void WarnOnLargeHistoryRequests(List requests, Action= OverlappingRequestsWarningCount) { _overlappingRequestsWarningSent = true; - debug($"Warning: history() has been called {OverlappingRequestsWarningCount}+ times with time windows overlapping" + - " the previous call. Re-fetching a long lookback repeatedly is slow: consider fetching history once and keeping" + - " it updated with a rolling window, consolidators or indicator warm up, or shortening the lookback."); + 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."); } } } diff --git a/Common/Scheduling/TimeMonitor.cs b/Common/Scheduling/TimeMonitor.cs index e47d1e91b9e4..c74b0840422b 100644 --- a/Common/Scheduling/TimeMonitor.cs +++ b/Common/Scheduling/TimeMonitor.cs @@ -112,8 +112,7 @@ protected virtual void ProcessConsumer(TimeConsumer consumer) consumer.AdditionalMinutesRequested++; if (consumer.Name != null) { - // name the long-running work upfront: an opaque isolator kill minutes later is much harder to act on. - // The first crossing of the one minute mark is the actionable heads-up, following ones are informational + // name the long-running work: the first minute crossing is the actionable heads-up, later ones are informational var message = $"TimeMonitor.ProcessConsumer(): '{consumer.Name}' has been executing for over {consumer.AdditionalMinutesRequested} minute(s)"; if (consumer.AdditionalMinutesRequested == 1) { diff --git a/Engine/AlgorithmTimeLimitManager.cs b/Engine/AlgorithmTimeLimitManager.cs index 03ac2bd56a5b..969aa8cac5c1 100644 --- a/Engine/AlgorithmTimeLimitManager.cs +++ b/Engine/AlgorithmTimeLimitManager.cs @@ -1,4 +1,4 @@ -/* +/* * QUANTCONNECT.COM - Democratizing Finance, Empowering Individuals. * Lean Algorithmic Trading Engine v2.0. Copyright 2014 QuantConnect Corporation. * @@ -54,9 +54,8 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider /// 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. - /// Elapsed time of a single time loop after which a warning is - /// logged, once per time step, so a slow handler is flagged well before the time loop maximum stops the - /// algorithm. Defaults to one minute; a non positive value disables the warning + /// Elapsed time of a single time loop after which a warning is logged, + /// once per time step. Defaults to one minute; a non positive value disables the warning public AlgorithmTimeLimitManager(ITokenBucket additionalTimeBucket, TimeSpan timeLoopMaximum, TimeSpan? timeLoopWarningThreshold = null) { _timeLoopMaximum = timeLoopMaximum; @@ -107,19 +106,18 @@ public IsolatorLimitResult IsWithinLimit() TimeSpan currentTimeStepElapsed; var message = IsOutOfTime(out currentTimeStepElapsed) ? GetErrorMessage(currentTimeStepElapsed) : string.Empty; - // warn early about an abnormally long time step: waiting for the time loop maximum to stop the algorithm - // costs many opaque minutes, while a warning naming the elapsed time is immediately actionable + // 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; - // override message flood protection: the message text repeats for every slow time step (at most one - // line per warning threshold of wall-clock time) and each occurrence is relevant + // override flood protection: the same text repeats for each slow time step and each occurrence matters Log.Error("AlgorithmTimeLimitManager.IsWithinLimit(): " + - $"the current algorithm time step has been executing for {currentTimeStepElapsed.TotalMinutes.ToStringInvariant("0.0")} minutes; " + - $"the algorithm will be stopped if a single time step exceeds {_timeLoopMaximum.TotalMinutes.ToStringInvariant()} minutes. " + - "If a scheduled event is running it is named in a 'TimeMonitor' log entry; other common causes are large" + - " history() requests, heavy work in data event handlers (e.g. on_data) or an infinite loop.", + $"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.", overrideMessageFloodProtection: true); } diff --git a/Engine/DataFeeds/UniverseSelection.cs b/Engine/DataFeeds/UniverseSelection.cs index aba2918b6506..6fa19732d885 100644 --- a/Engine/DataFeeds/UniverseSelection.cs +++ b/Engine/DataFeeds/UniverseSelection.cs @@ -482,10 +482,9 @@ public SecurityChanges HandleDelisting(BaseData data, bool isInternalFeed) } /// - /// Warns, once per algorithm, when option universe selections accumulate contracts beyond - /// 'option-universe-contracts-warning-threshold'. Every selected contract materializes into data subscriptions, - /// and wide filters, or many chained per-underlying option universes, are a recurring cause of out of memory - /// kills and multi-hour stalls. Warn only, never fail: the run may still succeed + /// Warns once per algorithm when option universes select more contracts than + /// 'option-universe-contracts-warning-threshold', a recurring cause of out of memory kills and stalls. + /// Warn only, never fail: the run may still succeed /// internal void WarnOnLargeOptionUniverseSelection(OptionChainUniverse universe) { @@ -494,8 +493,8 @@ internal void WarnOnLargeOptionUniverseSelection(OptionChainUniverse universe) return; } - // aggregate over all option universes: many chained per-underlying chains are as heavy as a single wide one. - // Note that 'Selected' includes the prepended underlying symbol, which is not a contract + // aggregate over all option universes: many small chains are as heavy as a single wide one. + // 'Selected' includes the prepended underlying symbol, which is not a contract var totalContracts = 0; var universeCount = 0; foreach (var kvp in _algorithm.UniverseManager) @@ -521,10 +520,9 @@ internal void WarnOnLargeOptionUniverseSelection(OptionChainUniverse universe) _optionUniverseSelectionSizeWarningSent = true; var latestCount = Math.Max(0, universe.Selected.Count - 1); _algorithm.Debug($"Warning: option universe selections have reached ~{totalContracts} contracts across {universeCount}" + - $" option universe(s), latest: {latestCount} contracts for {universe.Option.Symbol.Underlying.Value}. Each selected" + - " contract adds data subscriptions, which can slow down the algorithm and run it out of memory. Consider narrowing" + - " the universe filter (SetFilter/set_filter strikes and expiration ranges) or trading specific contracts found via" + - " OptionChain()/option_chain() and added with AddOptionContract/add_option_contract."); + $" universe(s), latest: {latestCount} for {universe.Option.Symbol.Underlying.Value}. Each contract adds data" + + " subscriptions, increasing time and memory usage. Narrow the filter (SetFilter/set_filter) or add specific" + + " contracts (AddOptionContract/add_option_contract)."); } private void RemoveSecurityFromUniverse( diff --git a/Engine/DataFeeds/ZipDataCacheProvider.cs b/Engine/DataFeeds/ZipDataCacheProvider.cs index a15ffb57df0d..e8554aabfcec 100644 --- a/Engine/DataFeeds/ZipDataCacheProvider.cs +++ b/Engine/DataFeeds/ZipDataCacheProvider.cs @@ -113,8 +113,7 @@ public Stream Fetch(string key) stream?.DisposeSafely(); if (err is OutOfMemoryException) { - // let the memory diagnostic bubble up: returning a null stream here would just resurface - // as a confusing downstream failure while the process is dying anyway + // let the memory diagnostic bubble up instead of resurfacing as a confusing downstream failure throw; } Log.Error(err, "Inner try/catch"); @@ -435,10 +434,9 @@ private bool Cache(string filename, out CachedZipFile cachedZip) } /// - /// Rethrows the given exception as an honest memory diagnostic if it is, or wraps, an . - /// Ionic wraps allocation failures while reading a zip into 'ZipException: Cannot read that as a ZipFile', which we would - /// otherwise log as a corrupt zip file and swallow, sending users down a data-integrity path when the process is actually - /// out of memory, usually due to too many subscriptions or too much data being requested + /// Rethrows as a memory diagnostic if the exception is, or wraps, an . + /// Ionic wraps allocation failures into 'ZipException: Cannot read that as a ZipFile', which would otherwise + /// be logged as a corrupt zip file and swallowed /// private static void RethrowIfOutOfMemory(Exception exception, string filename, string entryName) { @@ -448,7 +446,7 @@ private static void RethrowIfOutOfMemory(Exception exception, string filename, s { var entry = entryName != null ? "#" + entryName : string.Empty; throw new OutOfMemoryException("ZipDataCacheProvider.Fetch(): ran out of memory reading " + filename + entry + - ". This indicates memory exhaustion, not a corrupt data file: reduce the number of subscriptions" + + ". This is memory exhaustion, not a corrupt data file: reduce the number of subscriptions" + " (e.g. narrow option universe filters) or the amount of data requested.", exception); } } From 28a7334f56beb680406198083ce79f800ccffe5f Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Wed, 12 Aug 2026 18:38:23 -0400 Subject: [PATCH 07/11] Generalize code comments --- Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs b/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs index 12f579a41f71..842543d1f1ed 100644 --- a/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs +++ b/Tests/Engine/DataCacheProviders/ZipDataCacheProviderTests.cs @@ -55,7 +55,7 @@ public void MultiThreadReadWriteTest() public void FetchRethrowsOutOfMemoryAsMemoryDiagnostic() { // Ionic wraps the allocation failure into ZipException("Cannot read that as a ZipFile"), which used to be - // logged as a corrupt zip file and swallowed, see A-abb25be1. We want an honest memory diagnostic instead. + // logged as a corrupt zip file and swallowed. We want an honest memory diagnostic instead. using var dataCacheProvider = new ZipDataCacheProvider(new OutOfMemoryDataProvider()); var exception = Assert.Throws( From d02f6becc4943a2a90384619d4f48c47c93accec Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Thu, 13 Aug 2026 12:44:49 -0400 Subject: [PATCH 08/11] Harden large history request diagnostics Estimate tick history at 10 data points per second: one per second underestimates liquid symbols by 1-2 orders of magnitude (SPY 2013-10-07 sample data: ~10.7 trade and ~115 quote ticks per second), letting OOM-prone tick history requests slip under the warning threshold. Never throw from the diagnostics checks: failures while checking requests or emitting warnings are logged and disable the checks instead of interfering with the algorithm. --- Algorithm/QCAlgorithm.History.cs | 84 ++++++++++++++---------- Tests/Algorithm/AlgorithmHistoryTests.cs | 21 ++++++ 2 files changed, 69 insertions(+), 36 deletions(-) diff --git a/Algorithm/QCAlgorithm.History.cs b/Algorithm/QCAlgorithm.History.cs index 04059547dc86..afdd00def57a 100644 --- a/Algorithm/QCAlgorithm.History.cs +++ b/Algorithm/QCAlgorithm.History.cs @@ -1569,6 +1569,7 @@ 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; @@ -1582,50 +1583,60 @@ private sealed class LargeHistoryRequestDiagnostics /// public void WarnOnLargeHistoryRequests(List requests, Action debug) { - if (_largeRequestWarningSent && _overlappingRequestsWarningSent || requests.Count == 0) - { - return; - } - - long estimatedCells = 0; - var startUtc = DateTime.MaxValue; - var endUtc = DateTime.MinValue; - foreach (var request in requests) + try { - estimatedCells += EstimateDataCells(request); - if (request.StartTimeUtc < startUtc) + if (_largeRequestWarningSent && _overlappingRequestsWarningSent || requests.Count == 0) { - startUtc = request.StartTimeUtc; + return; } - if (request.EndTimeUtc > endUtc) + + long estimatedCells = 0; + var startUtc = DateTime.MaxValue; + var endUtc = DateTime.MinValue; + foreach (var request in requests) { - endUtc = request.EndTimeUtc; + 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 (!_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 (_consecutiveOverlappingRequests >= OverlappingRequestsWarningCount) + if (!_overlappingRequestsWarningSent && estimatedCells >= _cellsWarningThreshold / OverlappingRequestSizeDivisor) { - _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."); + 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); + } } /// @@ -1648,8 +1659,9 @@ private static long EstimateDataCells(HistoryRequest request) bars = tradableDays; break; case Resolution.Tick: - // unknowable upfront, use a conservative 1 data point per second of market time - bars = tradableDays * request.ExchangeHours.RegularMarketDuration.TotalSeconds; + // 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()); diff --git a/Tests/Algorithm/AlgorithmHistoryTests.cs b/Tests/Algorithm/AlgorithmHistoryTests.cs index 3fb18b916dcf..f4454d9b9158 100644 --- a/Tests/Algorithm/AlgorithmHistoryTests.cs +++ b/Tests/Algorithm/AlgorithmHistoryTests.cs @@ -4312,6 +4312,27 @@ public void WarnsOnLargeHistoryRequest() } } + [Test] + public void WarnsOnLargeTickHistoryRequest() + { + Config.Set("history-request-cells-warning-threshold", "1000000"); + try + { + var algorithm = CreateAlgorithmForHistoryWarningTests(); + var symbol = algorithm.AddEquity("SPY", Resolution.Tick).Symbol; + + // one market day estimated at 10 ticks per second: 234,000 bars x 5 columns > 1,000,000 cells. + // At 1 tick per second the estimate would stay under the threshold and miss the warning + algorithm.History(new[] { symbol }, TimeSpan.FromDays(1), Resolution.Tick); + + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("large history request"))); + } + finally + { + Config.Reset(); + } + } + [Test] public void DoesNotWarnOnSmallHistoryRequest() { From 6c27408e70c666b16f106aed34264cc6b9461a44 Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Thu, 13 Aug 2026 13:20:33 -0400 Subject: [PATCH 09/11] Generalize the large universe selection warning to all universe types Replace the option-only contract count warning with a check covering every universe. Because the cost of a selected symbol grows with the resolution its subscriptions are added at, the flat contract threshold becomes a per-resolution table ('universe-selection-size-warning- thresholds', a JSON object like {"Minute": 500}). All universes consume a single shared budget: each universe contributes selection size over its resolution's threshold, warning when the combined load reaches one, so many small selections across resolutions accumulate like a single wide one. The warning never throws: failures are logged and disable the check instead of interfering with the algorithm. --- Engine/DataFeeds/UniverseSelection.cs | 132 +++++++++++++----- .../DataFeeds/UniverseSelectionTests.cs | 95 +++++++++++-- 2 files changed, 186 insertions(+), 41 deletions(-) diff --git a/Engine/DataFeeds/UniverseSelection.cs b/Engine/DataFeeds/UniverseSelection.cs index 6fa19732d885..4363be9227c0 100644 --- a/Engine/DataFeeds/UniverseSelection.cs +++ b/Engine/DataFeeds/UniverseSelection.cs @@ -43,8 +43,19 @@ public class UniverseSelection private bool _initializedSecurityBenchmark; private bool _anyDoesNotHaveFundamentalDataWarningLogged; private readonly SecurityChangesConstructor _securityChangesConstructor; - private bool _optionUniverseSelectionSizeWarningSent; - private readonly int _optionUniverseContractsWarningThreshold = Config.GetInt("option-universe-contracts-warning-threshold", 500); + private bool _universeSelectionSizeWarningSent; + // the cost of a selected symbol grows with the resolution its subscriptions are added at, + // so the warning threshold is defined per resolution instead of as a single flat count + private readonly Dictionary _universeSelectionSizeWarningThresholds = Config.GetValue( + "universe-selection-size-warning-thresholds", + new Dictionary + { + { Resolution.Tick, 100 }, + { Resolution.Second, 250 }, + { Resolution.Minute, 500 }, + { Resolution.Hour, 1000 }, + { Resolution.Daily, 2000 }, + }); /// /// Initializes a new instance of the class @@ -187,10 +198,7 @@ public SecurityChanges ApplyUniverseSelection(Universe universe, DateTime dateTi // materialize the enumerable into a set for processing universe.Selected = selectSymbolsResult.ToHashSet(); - if (universe is OptionChainUniverse optionChainUniverse) - { - WarnOnLargeOptionUniverseSelection(optionChainUniverse); - } + WarnOnLargeUniverseSelection(universe); } // first check for no pending removals, even if the universe selection @@ -482,47 +490,107 @@ public SecurityChanges HandleDelisting(BaseData data, bool isInternalFeed) } /// - /// Warns once per algorithm when option universes select more contracts than - /// 'option-universe-contracts-warning-threshold', a recurring cause of out of memory kills and stalls. + /// Warns once per algorithm when universe selections grow past the per-resolution symbol thresholds in + /// 'universe-selection-size-warning-thresholds', a recurring cause of out of memory kills and stalls. + /// All universes consume a single shared subscription budget: each resolution's threshold defines the + /// full budget for symbols subscribed at that resolution, and each universe consumes a fraction of it, + /// so load still accumulates across universes of different resolutions. /// Warn only, never fail: the run may still succeed /// - internal void WarnOnLargeOptionUniverseSelection(OptionChainUniverse universe) + internal void WarnOnLargeUniverseSelection(Universe universe) { - if (_optionUniverseSelectionSizeWarningSent || _optionUniverseContractsWarningThreshold <= 0) + try { - return; - } + if (_universeSelectionSizeWarningSent) + { + return; + } - // aggregate over all option universes: many small chains are as heavy as a single wide one. - // 'Selected' includes the prepended underlying symbol, which is not a contract - var totalContracts = 0; - var universeCount = 0; - foreach (var kvp in _algorithm.UniverseManager) - { - if (kvp.Value is OptionChainUniverse optionUniverse && optionUniverse.Selected != null) + var load = 0d; + var universeCount = 0; + var selectedByResolution = new SortedDictionary(); + + void Accumulate(Universe target) { - totalContracts += Math.Max(0, optionUniverse.Selected.Count - 1); + if (target.Selected == null || !TryGetSizeWarningThreshold(target, out var resolution, out var threshold)) + { + return; + } + var selectionSize = GetSelectionSize(target); + load += selectionSize / (double)threshold; universeCount++; + selectedByResolution.TryGetValue(resolution, out var resolutionCount); + selectedByResolution[resolution] = resolutionCount + selectionSize; } + + foreach (var kvp in _algorithm.UniverseManager) + { + Accumulate(kvp.Value); + } + if (universeCount == 0) + { + // not registered in the universe manager, count the given universe only + Accumulate(universe); + } + + if (load < 1) + { + return; + } + + _universeSelectionSizeWarningSent = true; + var counts = string.Join(" and ", selectedByResolution.Select(pair => $"~{pair.Value} symbols at {pair.Key} resolution")); + var suggestion = universe is OptionChainUniverse + ? "Narrow the filter (SetFilter/set_filter) or add specific contracts (AddOptionContract/add_option_contract)." + : "Select fewer symbols or use a coarser universe resolution (UniverseSettings.Resolution/universe_settings.resolution)."; + _algorithm.Debug($"Warning: universe selections have reached {counts} across {universeCount} universe(s)," + + $" latest: {GetSelectionSize(universe)} from {GetUniverseName(universe)}. Each selected symbol adds data" + + $" subscriptions, increasing time and memory usage. {suggestion}"); } - if (universeCount == 0) + catch (Exception exception) { - // not registered in the universe manager, count the given universe only - universeCount = 1; - totalContracts = Math.Max(0, universe.Selected.Count - 1); + // diagnostics must never interfere with the algorithm: log, disable and move on + _universeSelectionSizeWarningSent = true; + Log.Error(exception); } + } - if (totalContracts < _optionUniverseContractsWarningThreshold) + /// + /// Gets the selection size warning threshold for the resolution the universe's members subscribe at. + /// False when the resolution is unavailable or warnings are disabled for it + /// + private bool TryGetSizeWarningThreshold(Universe universe, out Resolution resolution, out int threshold) + { + threshold = 0; + resolution = default; + var settings = universe.UniverseSettings; + if (settings == null) { - return; + return false; } + resolution = settings.Resolution; + return _universeSelectionSizeWarningThresholds.TryGetValue(resolution, out threshold) && threshold > 0; + } - _optionUniverseSelectionSizeWarningSent = true; - var latestCount = Math.Max(0, universe.Selected.Count - 1); - _algorithm.Debug($"Warning: option universe selections have reached ~{totalContracts} contracts across {universeCount}" + - $" universe(s), latest: {latestCount} for {universe.Option.Symbol.Underlying.Value}. Each contract adds data" + - " subscriptions, increasing time and memory usage. Narrow the filter (SetFilter/set_filter) or add specific" + - " contracts (AddOptionContract/add_option_contract)."); + /// + /// Number of symbols a universe selected. Option universe selections have the underlying + /// symbol prepended, which is not a contract + /// + private static int GetSelectionSize(Universe universe) + { + return universe is OptionChainUniverse + ? Math.Max(0, universe.Selected.Count - 1) + : universe.Selected.Count; + } + + /// + /// User-recognizable name for the universe emitting the warning + /// + private static string GetUniverseName(Universe universe) + { + return universe is OptionChainUniverse optionUniverse + ? optionUniverse.Option.Symbol.Underlying.Value + : universe.Configuration.Symbol.Value; } private void RemoveSecurityFromUniverse( diff --git a/Tests/Engine/DataFeeds/UniverseSelectionTests.cs b/Tests/Engine/DataFeeds/UniverseSelectionTests.cs index 607df5f6a9ff..ec9831316509 100644 --- a/Tests/Engine/DataFeeds/UniverseSelectionTests.cs +++ b/Tests/Engine/DataFeeds/UniverseSelectionTests.cs @@ -37,7 +37,8 @@ public class UniverseSelectionTests [Test] public void WarnsOnLargeOptionUniverseSelection() { - Config.Set("option-universe-contracts-warning-threshold", "10"); + // option universe subscriptions are added at minute resolution + Config.Set("universe-selection-size-warning-thresholds", "{\"Minute\": 10}"); try { var algorithm = new AlgorithmStub(new MockDataFeed()); @@ -49,17 +50,18 @@ public void WarnsOnLargeOptionUniverseSelection() // below the threshold: no warning universe.Selected = CreateOptionSelection(option.Symbol.Underlying, 5); - algorithm.DataManager.UniverseSelection.WarnOnLargeOptionUniverseSelection(universe); - Assert.AreEqual(0, OptionUniverseWarningCount(algorithm)); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(universe); + Assert.AreEqual(0, UniverseSizeWarningCount(algorithm)); // above the threshold: warns universe.Selected = CreateOptionSelection(option.Symbol.Underlying, 15); - algorithm.DataManager.UniverseSelection.WarnOnLargeOptionUniverseSelection(universe); - Assert.AreEqual(1, OptionUniverseWarningCount(algorithm)); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(universe); + Assert.AreEqual(1, UniverseSizeWarningCount(algorithm)); + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("SetFilter"))); // only warns once per algorithm - algorithm.DataManager.UniverseSelection.WarnOnLargeOptionUniverseSelection(universe); - Assert.AreEqual(1, OptionUniverseWarningCount(algorithm)); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(universe); + Assert.AreEqual(1, UniverseSizeWarningCount(algorithm)); } finally { @@ -67,9 +69,84 @@ public void WarnsOnLargeOptionUniverseSelection() } } - private static int OptionUniverseWarningCount(AlgorithmStub algorithm) + [Test] + public void LargeUniverseSelectionWarningIsResolutionAware() + { + Config.Set("universe-selection-size-warning-thresholds", "{\"Minute\": 10, \"Daily\": 50}"); + try + { + var algorithm = new AlgorithmStub(new MockDataFeed()); + algorithm.SetEndDate(new DateTime(2024, 12, 13)); + algorithm.SetStartDate(algorithm.EndDate.Subtract(TimeSpan.FromDays(10))); + algorithm.UniverseSettings.Resolution = Resolution.Daily; + algorithm.AddUniverse(coarse => Enumerable.Empty()); + // OnEndOfTimeStep will add all pending universe additions + algorithm.OnEndOfTimeStep(); + var universe = algorithm.UniverseManager.Values.First(); + + // over the minute threshold but under this universe's daily threshold: no warning + universe.Selected = CreateEquitySelection(20); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(universe); + Assert.AreEqual(0, UniverseSizeWarningCount(algorithm)); + + // over the daily threshold: warns with the generic suggestion + universe.Selected = CreateEquitySelection(60); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(universe); + Assert.AreEqual(1, UniverseSizeWarningCount(algorithm)); + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("Daily") && x.Contains("UniverseSettings.Resolution"))); + } + finally + { + Config.Reset(); + } + } + + [Test] + public void LargeUniverseSelectionWarningAggregatesAcrossResolutions() + { + Config.Set("universe-selection-size-warning-thresholds", "{\"Minute\": 10, \"Daily\": 50}"); + try + { + var algorithm = new AlgorithmStub(new MockDataFeed()); + algorithm.SetStartDate(2014, 6, 6); + var option = algorithm.AddOption("AAPL"); + algorithm.AddUniverse(fundamentals => Enumerable.Empty()); + // OnEndOfTimeStep will add all pending universe additions + algorithm.OnEndOfTimeStep(); + var optionUniverse = algorithm.UniverseManager.Values.OfType().Single(); + var equityUniverse = algorithm.UniverseManager.Values.Single(x => x is FundamentalUniverseFactory); + optionUniverse.UniverseSettings = new UniverseSettings(optionUniverse.UniverseSettings) { Resolution = Resolution.Minute }; + equityUniverse.UniverseSettings = new UniverseSettings(equityUniverse.UniverseSettings) { Resolution = Resolution.Daily }; + + // 8/10 minute contracts: under budget + optionUniverse.Selected = CreateOptionSelection(option.Symbol.Underlying, 8); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(optionUniverse); + Assert.AreEqual(0, UniverseSizeWarningCount(algorithm)); + + // 8/10 minute contracts + 30/50 daily symbols = 1.4 of the shared budget: warns, + // even though each universe is under its own resolution threshold + equityUniverse.Selected = CreateEquitySelection(30); + algorithm.DataManager.UniverseSelection.WarnOnLargeUniverseSelection(equityUniverse); + Assert.AreEqual(1, UniverseSizeWarningCount(algorithm)); + Assert.AreEqual(1, algorithm.DebugMessages.Count(x => x.Contains("~8 symbols at Minute resolution") && + x.Contains("~30 symbols at Daily resolution"))); + } + finally + { + Config.Reset(); + } + } + + private static int UniverseSizeWarningCount(AlgorithmStub algorithm) + { + return algorithm.DebugMessages.Count(x => x.Contains("universe selections")); + } + + private static HashSet CreateEquitySelection(int count) { - return algorithm.DebugMessages.Count(x => x.Contains("option universe selections")); + return Enumerable.Range(0, count) + .Select(i => Symbol.Create($"SYM{i}", SecurityType.Equity, Market.USA)) + .ToHashSet(); } private static HashSet CreateOptionSelection(Symbol underlying, int contractCount) From ab8def3940746bcbac398ac6fdbd4d0c8c4e932d Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Thu, 13 Aug 2026 13:26:42 -0400 Subject: [PATCH 10/11] Default the slow time step warning threshold to three minutes One minute is close enough to normal heavy steps (warm up, coarse selection days) to be noisy; three minutes keeps the warning early relative to the twenty minute kill while only firing on genuinely abnormal steps. --- Engine/AlgorithmManager.cs | 2 +- Engine/AlgorithmTimeLimitManager.cs | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/Engine/AlgorithmManager.cs b/Engine/AlgorithmManager.cs index 1bbbc6cb521e..2f55c56af726 100644 --- a/Engine/AlgorithmManager.cs +++ b/Engine/AlgorithmManager.cs @@ -102,7 +102,7 @@ public AlgorithmManager(bool liveMode, AlgorithmNodePacket job = null) 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-warning", 1)) + TimeSpan.FromMinutes(Config.GetDouble("algorithm-manager-time-loop-warning", 3)) ); } diff --git a/Engine/AlgorithmTimeLimitManager.cs b/Engine/AlgorithmTimeLimitManager.cs index 969aa8cac5c1..a0cd1678115d 100644 --- a/Engine/AlgorithmTimeLimitManager.cs +++ b/Engine/AlgorithmTimeLimitManager.cs @@ -55,11 +55,11 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider /// 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. /// Elapsed time of a single time loop after which a warning is logged, - /// once per time step. Defaults to one minute; a non positive value disables the warning + /// once per time step. Defaults to three minutes; a non positive value disables the warning public AlgorithmTimeLimitManager(ITokenBucket additionalTimeBucket, TimeSpan timeLoopMaximum, TimeSpan? timeLoopWarningThreshold = null) { _timeLoopMaximum = timeLoopMaximum; - _timeLoopWarningThreshold = timeLoopWarningThreshold ?? TimeSpan.FromMinutes(1); + _timeLoopWarningThreshold = timeLoopWarningThreshold ?? TimeSpan.FromMinutes(3); AdditionalTimeBucket = additionalTimeBucket; _currentTimeStepTime = new ReferenceWrapper(DateTime.MinValue); } From 1a685307fa8ee0ce8e431510f84af515cefafa74 Mon Sep 17 00:00:00 2001 From: Jhonathan Abreu Date: Thu, 13 Aug 2026 13:50:34 -0400 Subject: [PATCH 11/11] Surface time limit warnings in the user's logs The slow time step and long-running scheduled event warnings only went to the engine log, which does not reach the user's log file. Both now also route through the result handler's debug messages via an optional user warning handler, wired in AlgorithmManager.Run and BaseRealTimeHandler.Setup. Only the first scheduled event minute crossing is surfaced to the user; later crossings stay engine-side to avoid flooding user logs. --- Common/Scheduling/TimeMonitor.cs | 13 ++++++++++--- Engine/AlgorithmManager.cs | 2 ++ Engine/AlgorithmTimeLimitManager.cs | 16 +++++++++++----- Engine/RealTime/BaseRealTimeHandler.cs | 3 ++- Tests/Common/IsolatorLimitResultProviderTests.cs | 6 ++++++ Tests/Engine/AlgorithmTimeLimitManagerTests.cs | 10 +++++++++- 6 files changed, 40 insertions(+), 10 deletions(-) diff --git a/Common/Scheduling/TimeMonitor.cs b/Common/Scheduling/TimeMonitor.cs index c74b0840422b..3285593ee374 100644 --- a/Common/Scheduling/TimeMonitor.cs +++ b/Common/Scheduling/TimeMonitor.cs @@ -36,6 +36,12 @@ public class TimeMonitor : IDisposable /// in `IsolatorLimitResultProviderTests.cs protected List TimeConsumers { get; init; } + /// + /// 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 + /// + public Action UserWarningHandler { get; set; } + /// /// Returns the number of time consumers currently being monitored /// @@ -113,14 +119,15 @@ protected virtual void ProcessConsumer(TimeConsumer consumer) if (consumer.Name != null) { // name the long-running work: the first minute crossing is the actionable heads-up, later ones are informational - var message = $"TimeMonitor.ProcessConsumer(): '{consumer.Name}' has been executing for over {consumer.AdditionalMinutesRequested} minute(s)"; + var message = $"'{consumer.Name}' has been executing for over {consumer.AdditionalMinutesRequested} minute(s)"; if (consumer.AdditionalMinutesRequested == 1) { - Log.Error($"{message}. It will be stopped once the algorithm time loop limit is exhausted"); + 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(message); + Log.Trace($"TimeMonitor.ProcessConsumer(): {message}"); } } } diff --git a/Engine/AlgorithmManager.cs b/Engine/AlgorithmManager.cs index 2f55c56af726..10d2853ea005 100644 --- a/Engine/AlgorithmManager.cs +++ b/Engine/AlgorithmManager.cs @@ -124,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; diff --git a/Engine/AlgorithmTimeLimitManager.cs b/Engine/AlgorithmTimeLimitManager.cs index a0cd1678115d..12d65bf705e3 100644 --- a/Engine/AlgorithmTimeLimitManager.cs +++ b/Engine/AlgorithmTimeLimitManager.cs @@ -44,6 +44,12 @@ public class AlgorithmTimeLimitManager : IIsolatorLimitResultProvider /// public ITokenBucket AdditionalTimeBucket { get; } + /// + /// 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 + /// + public Action UserWarningHandler { get; set; } + /// /// Initializes a new instance of to manage the /// creation of instances as it pertains to the @@ -112,13 +118,13 @@ public IsolatorLimitResult IsWithinLimit() && _timeLoopWarningThreshold > TimeSpan.Zero && currentTimeStepElapsed > _timeLoopWarningThreshold) { _timeStepWarningSent = true; - // override flood protection: the same text repeats for each slow time step and each occurrence matters - Log.Error("AlgorithmTimeLimitManager.IsWithinLimit(): " + - $"the current time step has been executing for {currentTimeStepElapsed.TotalMinutes.ToStringInvariant("0.0")} minutes" + + 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.", - overrideMessageFloodProtection: true); + " 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); diff --git a/Engine/RealTime/BaseRealTimeHandler.cs b/Engine/RealTime/BaseRealTimeHandler.cs index d106b73bef4f..ef5a0b3f722d 100644 --- a/Engine/RealTime/BaseRealTimeHandler.cs +++ b/Engine/RealTime/BaseRealTimeHandler.cs @@ -119,7 +119,8 @@ public virtual void Setup(IAlgorithm algorithm, AlgorithmNodePacket job, IResult { Algorithm = algorithm; ResultHandler = resultHandler; - TimeMonitor = new TimeMonitor(GetTimeMonitorTimeout()); + // surface long-running scheduled event warnings in the user's logs, not just the engine log + TimeMonitor = new TimeMonitor(GetTimeMonitorTimeout()) { UserWarningHandler = message => ResultHandler?.DebugMessage(message) }; IsolatorLimitProvider = isolatorLimitProvider; if (job.Language == Language.CSharp) diff --git a/Tests/Common/IsolatorLimitResultProviderTests.cs b/Tests/Common/IsolatorLimitResultProviderTests.cs index 14e554c70c73..a6edcef53028 100644 --- a/Tests/Common/IsolatorLimitResultProviderTests.cs +++ b/Tests/Common/IsolatorLimitResultProviderTests.cs @@ -153,6 +153,8 @@ public void ConsumeNamesTheWorkWhenRequestingAdditionalTime() { var logHandler = new QueueLogHandler(); Log.LogHandler = logHandler; + var userWarnings = new List(); + _timeMonitor.UserWarningHandler = userWarnings.Add; var timeProvider = new ManualTimeProvider(new DateTime(2000, 01, 01)); var provider = new FakeIsolatorLimitResultProvider(); @@ -171,6 +173,9 @@ public void ConsumeNamesTheWorkWhenRequestingAdditionalTime() Assert.AreEqual(1, provider.Invocations.Count); Assert.AreEqual(1, logHandler.Logs.Count( entry => entry.Message.Contains("'My Slow Scheduled Event' has been executing for over 1 minute"))); + // the warning also reaches the user + Assert.AreEqual(1, userWarnings.Count( + message => message.Contains("'My Slow Scheduled Event' has been executing for over 1 minute"))); // give time to the monitor to register the time consumer ended _timeMonitorEvent.WaitOne(); @@ -179,6 +184,7 @@ public void ConsumeNamesTheWorkWhenRequestingAdditionalTime() finally { Log.LogHandler = previousLogHandler; + _timeMonitor.UserWarningHandler = null; } } diff --git a/Tests/Engine/AlgorithmTimeLimitManagerTests.cs b/Tests/Engine/AlgorithmTimeLimitManagerTests.cs index 16c501327b7c..144c9c944594 100644 --- a/Tests/Engine/AlgorithmTimeLimitManagerTests.cs +++ b/Tests/Engine/AlgorithmTimeLimitManagerTests.cs @@ -69,8 +69,10 @@ public void WarnsOnceOnLongTimeStepWithoutFailing() var logHandler = new QueueLogHandler(); Log.LogHandler = logHandler; + var userWarnings = new List(); var timeManager = new AlgorithmTimeLimitManager(TokenBucket.Null, TimeSpan.FromMinutes(20), timeLoopWarningThreshold: TimeSpan.FromMilliseconds(5)); + timeManager.UserWarningHandler = userWarnings.Add; timeManager.StartNewTimeStep(); // the first call initializes the current time step start time Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); @@ -80,11 +82,13 @@ public void WarnsOnceOnLongTimeStepWithoutFailing() var result = timeManager.IsWithinLimit(); Assert.IsTrue(result.IsWithinCustomLimits, result.ErrorMessage); Assert.AreEqual(1, WarningCount(logHandler)); + Assert.AreEqual(1, userWarnings.Count(x => x.Contains("time step has been executing"))); // only warns once per time step Thread.Sleep(20); Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); Assert.AreEqual(1, WarningCount(logHandler)); + Assert.AreEqual(1, userWarnings.Count); // a new slow time step warns again timeManager.StartNewTimeStep(); @@ -92,6 +96,7 @@ public void WarnsOnceOnLongTimeStepWithoutFailing() Thread.Sleep(50); Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); Assert.AreEqual(2, WarningCount(logHandler)); + Assert.AreEqual(2, userWarnings.Count); } finally { @@ -108,14 +113,17 @@ public void DoesNotWarnOnFastTimeStep() var logHandler = new QueueLogHandler(); Log.LogHandler = logHandler; - // default one minute warning threshold + // default three minute warning threshold + var userWarnings = new List(); var timeManager = new AlgorithmTimeLimitManager(TokenBucket.Null, TimeSpan.FromMinutes(20)); + timeManager.UserWarningHandler = userWarnings.Add; timeManager.StartNewTimeStep(); Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); Thread.Sleep(20); Assert.IsTrue(timeManager.IsWithinLimit().IsWithinCustomLimits); Assert.AreEqual(0, WarningCount(logHandler)); + Assert.AreEqual(0, userWarnings.Count); } finally {