diff --git a/freqtrade/freqai/freqai_interface.py b/freqtrade/freqai/freqai_interface.py index 77203b4f0..f68b45b99 100644 --- a/freqtrade/freqai/freqai_interface.py +++ b/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 diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index cf9b6e17b..d24732e12 100644 --- a/freqtrade/freqtradebot.py +++ b/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 diff --git a/freqtrade/util/__init__.py b/freqtrade/util/__init__.py index f7e63d9d3..b85b36ffb 100644 --- a/freqtrade/util/__init__.py +++ b/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', ] diff --git a/freqtrade/util/measure_time.py b/freqtrade/util/measure_time.py new file mode 100644 index 000000000..8266adfc0 --- /dev/null +++ b/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 diff --git a/tests/utils/test_measure_time.py b/tests/utils/test_measure_time.py new file mode 100644 index 000000000..dac509907 --- /dev/null +++ b/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