Merge pull request #3168 from freqtrade/fix_pairlist_caching

Fix pairlist caching

freqtrade/pairlist/IPairList.py

@@ -9,6 +9,8 @@ from abc import ABC, abstractmethod, abstractproperty
 from copy import deepcopy
 from typing import Any, Dict, List
 
+from cachetools import TTLCache, cached
+
 from freqtrade.exchange import market_is_active
 
 logger = logging.getLogger(__name__)
@@ -31,6 +33,9 @@ class IPairList(ABC):
         self._config = config
         self._pairlistconfig = pairlistconfig
         self._pairlist_pos = pairlist_pos
+        self.refresh_period = self._pairlistconfig.get('refresh_period', 1800)
+        self._last_refresh = 0
+        self._log_cache = TTLCache(maxsize=1024, ttl=self.refresh_period)
 
     @property
     def name(self) -> str:
@@ -40,6 +45,24 @@ class IPairList(ABC):
         """
         return self.__class__.__name__
 
+    def log_on_refresh(self, logmethod, message: str) -> None:
+        """
+        Logs message - not more often than "refresh_period" to avoid log spamming
+        Logs the log-message as debug as well to simplify debugging.
+        :param logmethod: Function that'll be called. Most likely `logger.info`.
+        :param message: String containing the message to be sent to the function.
+        :return: None.
+        """
+
+        @cached(cache=self._log_cache)
+        def _log_on_refresh(message: str):
+            logmethod(message)
+
+        # Log as debug first
+        logger.debug(message)
+        # Call hidden function.
+        _log_on_refresh(message)
+
     @abstractproperty
     def needstickers(self) -> bool:
         """

freqtrade/pairlist/PrecisionFilter.py

@@ -39,8 +39,9 @@ class PrecisionFilter(IPairList):
         stop_gap_price = self._exchange.price_to_precision(ticker["symbol"], stop_price * 0.99)
         logger.debug(f"{ticker['symbol']} - {sp} : {stop_gap_price}")
         if sp <= stop_gap_price:
-            logger.info(f"Removed {ticker['symbol']} from whitelist, "
-                        f"because stop price {sp} would be <= stop limit {stop_gap_price}")
+            self.log_on_refresh(logger.info,
+                                f"Removed {ticker['symbol']} from whitelist, "
+                                f"because stop price {sp} would be <= stop limit {stop_gap_price}")
             return False
         return True
 

freqtrade/pairlist/PriceFilter.py

@@ -41,8 +41,8 @@ class PriceFilter(IPairList):
                                                                     ticker['last'])
         changeperc = (compare - ticker['last']) / ticker['last']
         if changeperc > self._low_price_ratio:
-            logger.info(f"Removed {ticker['symbol']} from whitelist, "
-                        f"because 1 unit is {changeperc * 100:.3f}%")
+            self.log_on_refresh(logger.info, f"Removed {ticker['symbol']} from whitelist, "
+                                             f"because 1 unit is {changeperc * 100:.3f}%")
             return False
         return True
 

freqtrade/pairlist/SpreadFilter.py

@@ -49,9 +49,9 @@ class SpreadFilter(IPairList):
             if 'bid' in ticker and 'ask' in ticker:
                 spread = 1 - ticker['bid'] / ticker['ask']
                 if not ticker or spread > self._max_spread_ratio:
-                    logger.info(f"Removed {ticker['symbol']} from whitelist, "
-                                f"because spread {spread * 100:.3f}% >"
-                                f"{self._max_spread_ratio * 100}%")
+                    self.log_on_refresh(logger.info, f"Removed {ticker['symbol']} from whitelist, "
+                                                     f"because spread {spread * 100:.3f}% >"
+                                                     f"{self._max_spread_ratio * 100}%")
                     pairlist.remove(p)
             else:
                 pairlist.remove(p)

freqtrade/pairlist/VolumePairList.py

@@ -39,7 +39,6 @@ class VolumePairList(IPairList):
         if not self._validate_keys(self._sort_key):
             raise OperationalException(
                 f'key {self._sort_key} not in {SORT_VALUES}')
-        self._last_refresh = 0
 
     @property
     def needstickers(self) -> bool:
@@ -68,16 +67,18 @@ class VolumePairList(IPairList):
         :return: new whitelist
         """
         # Generate dynamic whitelist
-        if self._last_refresh + self.refresh_period < datetime.now().timestamp():
+        # Must always run if this pairlist is not the first in the list.
+        if (self._pairlist_pos != 0 or
+                (self._last_refresh + self.refresh_period < datetime.now().timestamp())):
+
             self._last_refresh = int(datetime.now().timestamp())
-            return self._gen_pair_whitelist(pairlist,
-                                            tickers,
-                                            self._config['stake_currency'],
-                                            self._sort_key,
-                                            self._min_value
-                                            )
+            pairs = self._gen_pair_whitelist(pairlist, tickers,
+                                             self._config['stake_currency'],
+                                             self._sort_key, self._min_value)
         else:
-            return pairlist
+            pairs = pairlist
+        self.log_on_refresh(logger.info, f"Searching {self._number_pairs} pairs: {pairs}")
+        return pairs
 
     def _gen_pair_whitelist(self, pairlist: List[str], tickers: Dict,
                             base_currency: str, key: str, min_val: int) -> List[str]:
@@ -88,7 +89,6 @@ class VolumePairList(IPairList):
         :param tickers: Tickers (from exchange.get_tickers()).
         :return: List of pairs
         """
-
         if self._pairlist_pos == 0:
             # If VolumePairList is the first in the list, use fresh pairlist
             # Check if pair quote currency equals to the stake currency.
@@ -109,6 +109,5 @@ class VolumePairList(IPairList):
         pairs = self._verify_blacklist(pairs, aswarning=False)
         # Limit to X number of pairs
         pairs = pairs[:self._number_pairs]
-        logger.info(f"Searching {self._number_pairs} pairs: {pairs}")
 
         return pairs

tests/pairlist/test_pairlist.py

@@ -46,6 +46,28 @@ def static_pl_conf(whitelist_conf):
     return whitelist_conf
 
 
+def test_log_on_refresh(mocker, static_pl_conf, markets, tickers):
+    mocker.patch.multiple('freqtrade.exchange.Exchange',
+                          markets=PropertyMock(return_value=markets),
+                          exchange_has=MagicMock(return_value=True),
+                          get_tickers=tickers
+                          )
+    freqtrade = get_patched_freqtradebot(mocker, static_pl_conf)
+    logmock = MagicMock()
+    # Assign starting whitelist
+    pl = freqtrade.pairlists._pairlists[0]
+    pl.log_on_refresh(logmock, 'Hello world')
+    assert logmock.call_count == 1
+    pl.log_on_refresh(logmock, 'Hello world')
+    assert logmock.call_count == 1
+    assert pl._log_cache.currsize == 1
+    assert ('Hello world',) in pl._log_cache._Cache__data
+
+    pl.log_on_refresh(logmock, 'Hello world2')
+    assert logmock.call_count == 2
+    assert pl._log_cache.currsize == 2
+
+
 def test_load_pairlist_noexist(mocker, markets, default_conf):
     bot = get_patched_freqtradebot(mocker, default_conf)
     mocker.patch('freqtrade.exchange.Exchange.markets', PropertyMock(return_value=markets))