Merge pull request #10097 from freqtrade/feat/measure_time

Add "measure time" to warn users about strategies taking excessive time

freqtrade/freqai/freqai_interface.py

@@ -718,9 +718,6 @@ class IFreqaiModel(ABC):
             if self.pair_it == self.total_pairs:
                 logger.info(
                     f'Total time spent inferencing pairlist {self.inference_time:.2f} seconds')
-                if self.inference_time > 0.25 * self.base_tf_seconds:
-                    logger.warning("Inference took over 25% of the candle time. Reduce pairlist to"
-                                   " avoid blinding open trades and degrading performance.")
                 self.pair_it = 0
                 self.inference_time = 0
         return

freqtrade/freqtradebot.py

@@ -37,6 +37,7 @@ from freqtrade.rpc.rpc_types import (ProfitLossStr, RPCCancelMsg, RPCEntryMsg, R
                                      RPCExitMsg, RPCProtectionMsg)
 from freqtrade.strategy.interface import IStrategy
 from freqtrade.strategy.strategy_wrapper import strategy_safe_wrapper
+from freqtrade.util import MeasureTime
 from freqtrade.util.migrations import migrate_binance_futures_names
 from freqtrade.wallets import Wallets
 
@@ -140,6 +141,16 @@ class FreqtradeBot(LoggingMixin):
         # Initialize protections AFTER bot start - otherwise parameters are not loaded.
         self.protections = ProtectionManager(self.config, self.strategy.protections)
 
+        def log_took_too_long(duration: float, time_limit: float):
+            logger.warning(
+                f"Strategy analysis took {duration:.2f}, which is 25% of the timeframe. "
+                "This can lead to delayed orders and missed signals."
+                "Consider either reducing the amount of work your strategy performs "
+                "or reduce the amount of pairs in the Pairlist."
+            )
+
+        self._measure_execution = MeasureTime(log_took_too_long, timeframe_secs * 0.25)
+
     def notify_status(self, msg: str, msg_type=RPCMessageType.STATUS) -> None:
         """
         Public method for users of this class (worker, etc.) to send notifications
@@ -224,7 +235,8 @@ class FreqtradeBot(LoggingMixin):
         strategy_safe_wrapper(self.strategy.bot_loop_start, supress_error=True)(
             current_time=datetime.now(timezone.utc))
 
-        self.strategy.analyze(self.active_pair_whitelist)
+        with self._measure_execution:
+            self.strategy.analyze(self.active_pair_whitelist)
 
         with self._exit_lock:
             # Check for exchange cancellations, timeouts and user requested replace

freqtrade/util/__init__.py

@@ -3,6 +3,7 @@ from freqtrade.util.datetime_helpers import (dt_floor_day, dt_from_ts, dt_humani
                                              format_ms_time, shorten_date)
 from freqtrade.util.formatters import decimals_per_coin, fmt_coin, round_value
 from freqtrade.util.ft_precise import FtPrecise
+from freqtrade.util.measure_time import MeasureTime
 from freqtrade.util.periodic_cache import PeriodicCache
 from freqtrade.util.template_renderer import render_template, render_template_with_fallback  # noqa
 
@@ -24,4 +25,5 @@ __all__ = [
     'decimals_per_coin',
     'round_value',
     'fmt_coin',
+    'MeasureTime',
 ]

freqtrade/util/measure_time.py

@@ -0,0 +1,43 @@
+import logging
+import time
+from typing import Callable
+
+from cachetools import TTLCache
+
+
+logger = logging.getLogger(__name__)
+
+
+class MeasureTime:
+    """
+    Measure the time of a block of code and call a callback if the time limit is exceeded.
+    """
+    def __init__(
+            self, callback: Callable[[float, float], None], time_limit: float, ttl: int = 3600 * 4):
+        """
+        :param callback: The callback to call if the time limit is exceeded.
+            This callback will be called once every "ttl" seconds,
+            with the parameters "duration" (in seconds) and
+            "time limit" - representing the passed in time limit.
+        :param time_limit: The time limit in seconds.
+        :param ttl: The time to live of the cache in seconds.
+            defaults to 4 hours.
+        """
+        self._callback = callback
+        self._time_limit = time_limit
+        self.__cache: TTLCache = TTLCache(maxsize=1, ttl=ttl)
+
+    def __enter__(self):
+        self._start = time.time()
+
+    def __exit__(self, *args):
+        end = time.time()
+        if self.__cache.get('value'):
+            return
+        duration = end - self._start
+
+        if duration < self._time_limit:
+            return
+        self._callback(duration, self._time_limit)
+
+        self.__cache['value'] = True

tests/utils/test_measure_time.py

@@ -0,0 +1,34 @@
+from unittest.mock import MagicMock
+
+import time_machine
+
+from freqtrade.util import MeasureTime
+
+
+def test_measure_time():
+
+    callback = MagicMock()
+    with time_machine.travel("2021-09-01 05:00:00 +00:00", tick=False) as t:
+
+        measure = MeasureTime(callback, 5, ttl=60)
+        with measure:
+            pass
+
+        assert callback.call_count == 0
+
+        with measure:
+            t.shift(10)
+
+        assert callback.call_count == 1
+        callback.reset_mock()
+        with measure:
+            t.shift(10)
+        assert callback.call_count == 0
+
+        callback.reset_mock()
+        # Shift past the ttl
+        t.shift(45)
+
+        with measure:
+            t.shift(10)
+        assert callback.call_count == 1