From 2297b3ed55f035f8460eb7a292a307070849ed72 Mon Sep 17 00:00:00 2001 From: Matthias Date: Wed, 17 Apr 2024 20:13:02 +0200 Subject: [PATCH 1/7] Split timeframe_to_secs from loggingmixin init --- freqtrade/freqtradebot.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index 0184741ff..a3ab559fa 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -117,7 +117,8 @@ class FreqtradeBot(LoggingMixin): # Protect exit-logic from forcesell and vice versa self._exit_lock = Lock() - LoggingMixin.__init__(self, logger, timeframe_to_seconds(self.strategy.timeframe)) + timeframe_secs = timeframe_to_seconds(self.strategy.timeframe) + LoggingMixin.__init__(self, logger, timeframe_secs) self._schedule = Scheduler() From 3c8366e60946998aa3da4f1eb92bfbdc0b63ce6f Mon Sep 17 00:00:00 2001 From: Matthias Date: Wed, 17 Apr 2024 20:51:09 +0200 Subject: [PATCH 2/7] Add measure_time module to measure time taken by functions --- freqtrade/util/__init__.py | 2 ++ freqtrade/util/measure_time.py | 42 ++++++++++++++++++++++++++++++++++ 2 files changed, 44 insertions(+) create mode 100644 freqtrade/util/measure_time.py 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..beb43c27e --- /dev/null +++ b/freqtrade/util/measure_time.py @@ -0,0 +1,42 @@ +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[[int, int], None], time_limit: int, 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. + """ + self._callback = callback + self._time_limit = time_limit + self.__cache = 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 From c6a50b3c064f2698137b7d544e24f65a8c0646db Mon Sep 17 00:00:00 2001 From: Matthias Date: Wed, 17 Apr 2024 20:53:49 +0200 Subject: [PATCH 3/7] Use MeasureTime to warn if a strategy takes too long using 25% of the candle as reference time for now. --- freqtrade/freqtradebot.py | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index a3ab559fa..f6e6a9129 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: int, time_limit: int): + 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 cancelations, timeouts and user requested replace From 5eeb96fa96d6352e6548bd4388cd8eb286eee62a Mon Sep 17 00:00:00 2001 From: Matthias Date: Wed, 17 Apr 2024 20:57:18 +0200 Subject: [PATCH 4/7] Add test for measure_time --- tests/utils/test_measure_time.py | 34 ++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) create mode 100644 tests/utils/test_measure_time.py 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 From 82482ec159938d3098f88ac612d67b05bfc2bf16 Mon Sep 17 00:00:00 2001 From: Matthias Date: Wed, 17 Apr 2024 20:58:58 +0200 Subject: [PATCH 5/7] Fix / improve types --- freqtrade/freqtradebot.py | 2 +- freqtrade/util/measure_time.py | 6 ++++-- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index f6e6a9129..578bb7cd6 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -141,7 +141,7 @@ 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: int, time_limit: int): + 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." diff --git a/freqtrade/util/measure_time.py b/freqtrade/util/measure_time.py index beb43c27e..f60766016 100644 --- a/freqtrade/util/measure_time.py +++ b/freqtrade/util/measure_time.py @@ -13,7 +13,8 @@ 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[[int, int], None], time_limit: int, ttl: int = 3600 * 4): + 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, @@ -21,10 +22,11 @@ class MeasureTime: "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(maxsize=1, ttl=ttl) + self.__cache: TTLCache = TTLCache(maxsize=1, ttl=ttl) def __enter__(self): self._start = time.time() From 6a570bd82e777e2b4e3c465001a33158a6c3ab3b Mon Sep 17 00:00:00 2001 From: Matthias Date: Thu, 18 Apr 2024 06:41:14 +0200 Subject: [PATCH 6/7] Fix excessive whitespace --- freqtrade/util/measure_time.py | 1 - 1 file changed, 1 deletion(-) diff --git a/freqtrade/util/measure_time.py b/freqtrade/util/measure_time.py index f60766016..8266adfc0 100644 --- a/freqtrade/util/measure_time.py +++ b/freqtrade/util/measure_time.py @@ -11,7 +11,6 @@ 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): From 0a7ed55adef63651f00ae9169cff3a8e8fb2a385 Mon Sep 17 00:00:00 2001 From: Matthias Date: Thu, 18 Apr 2024 21:01:48 +0200 Subject: [PATCH 7/7] Reduce duplicate warning --- freqtrade/freqai/freqai_interface.py | 3 --- freqtrade/freqtradebot.py | 2 +- 2 files changed, 1 insertion(+), 4 deletions(-) diff --git a/freqtrade/freqai/freqai_interface.py b/freqtrade/freqai/freqai_interface.py index 60fae421b..dae97468e 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 578bb7cd6..70c670000 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -145,7 +145,7 @@ class FreqtradeBot(LoggingMixin): 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, " + "Consider either reducing the amount of work your strategy performs " "or reduce the amount of pairs in the Pairlist." )