adelorenzo/stable
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge pull request #2253 from hroff-1902/backtesting-improve-logs

Browse Source 
Improve logs for backtesting
This commit is contained in:
hroff-1902 2019-09-14 11:23:46 +03:00 committed by GitHub
commit 76e45883bd
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 103 additions and 91 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

44
freqtrade/optimize/backtesting.py
View File

@ -239,14 +239,16 @@ class Backtesting:
stake_amount: float, max_open_trades: int) -> Optional[BacktestResult]:
trade = Trade(
pair=pair,
open_rate=buy_row.open,
open_date=buy_row.date,
stake_amount=stake_amount,
amount=stake_amount / buy_row.open,
fee_open=self.fee,
fee_close=self.fee
fee_close=self.fee,
is_open=True,
)
logger.debug(f"{pair} - Backtesting emulates creation of new trade: {trade}.")
# calculate win/lose forwards from buy point
for sell_row in partial_ticker:
if max_open_trades > 0:
@ -289,23 +291,25 @@ class Backtesting:
if partial_ticker:
# no sell condition found - trade stil open at end of backtest period
sell_row = partial_ticker[-1]
btr = BacktestResult(pair=pair,
profit_percent=trade.calc_profit_percent(rate=sell_row.open),
profit_abs=trade.calc_profit(rate=sell_row.open),
open_time=buy_row.date,
close_time=sell_row.date,
trade_duration=int((
sell_row.date - buy_row.date).total_seconds() // 60),
open_index=buy_row.Index,
close_index=sell_row.Index,
open_at_end=True,
open_rate=buy_row.open,
close_rate=sell_row.open,
sell_reason=SellType.FORCE_SELL
)
logger.debug('Force_selling still open trade %s with %s perc - %s', btr.pair,
btr.profit_percent, btr.profit_abs)
return btr
bt_res = BacktestResult(pair=pair,
profit_percent=trade.calc_profit_percent(rate=sell_row.open),
profit_abs=trade.calc_profit(rate=sell_row.open),
open_time=buy_row.date,
close_time=sell_row.date,
trade_duration=int((
sell_row.date - buy_row.date).total_seconds() // 60),
open_index=buy_row.Index,
close_index=sell_row.Index,
open_at_end=True,
open_rate=buy_row.open,
close_rate=sell_row.open,
sell_reason=SellType.FORCE_SELL
)
logger.debug(f"{pair} - Force selling still open trade, "
f"profit percent: {bt_res.profit_percent}, "
f"profit abs: {bt_res.profit_abs}")
return bt_res
return None
def backtest(self, args: Dict) -> DataFrame:
@ -384,6 +388,8 @@ class Backtesting:
max_open_trades)
if trade_entry:
logger.debug(f"{pair} - Locking pair till "
f"close_time={trade_entry.close_time}")
lock_pair_until[pair] = trade_entry.close_time
trades.append(trade_entry)
else:

54
freqtrade/persistence.py
View File

@ -1,7 +1,6 @@
"""
This module contains the class to persist trades into SQLite
"""
import logging
from datetime import datetime
from decimal import Decimal
@ -19,8 +18,10 @@ from sqlalchemy.pool import StaticPool
from freqtrade import OperationalException
logger = logging.getLogger(__name__)
_DECL_BASE: Any = declarative_base()
_SQL_DOCS_URL = 'http://docs.sqlalchemy.org/en/latest/core/engines.html#database-urls'
@ -209,7 +210,7 @@ class Trade(_DECL_BASE):
ticker_interval = Column(Integer, nullable=True)
def __repr__(self):
open_since = arrow.get(self.open_date).humanize() if self.is_open else 'closed'
open_since = self.open_date.strftime('%Y-%m-%d %H:%M:%S') if self.is_open else 'closed'
return (f'Trade(id={self.id}, pair={self.pair}, amount={self.amount:.8f}, '
f'open_rate={self.open_rate:.8f}, open_since={open_since})')
@ -250,7 +251,6 @@ class Trade(_DECL_BASE):
:param initial: Called to initiate stop_loss.
Skips everything if self.stop_loss is already set.
"""
if initial and not (self.stop_loss is None or self.stop_loss == 0):
# Don't modify if called with initial and nothing to do
return
@ -259,7 +259,7 @@ class Trade(_DECL_BASE):
# no stop loss assigned yet
if not self.stop_loss:
logger.debug("assigning new stop loss")
logger.debug(f"{self.pair} - Assigning new stoploss...")
self.stop_loss = new_loss
self.stop_loss_pct = -1 * abs(stoploss)
self.initial_stop_loss = new_loss
@ -269,21 +269,20 @@ class Trade(_DECL_BASE):
# evaluate if the stop loss needs to be updated
else:
if new_loss > self.stop_loss: # stop losses only walk up, never down!
logger.debug(f"{self.pair} - Adjusting stoploss...")
self.stop_loss = new_loss
self.stop_loss_pct = -1 * abs(stoploss)
self.stoploss_last_update = datetime.utcnow()
logger.debug("adjusted stop loss")
else:
logger.debug("keeping current stop loss")
logger.debug(f"{self.pair} - Keeping current stoploss...")
logger.debug(
f"{self.pair} - current price {current_price:.8f}, "
f"bought at {self.open_rate:.8f} and calculated "
f"stop loss is at: {self.initial_stop_loss:.8f} initial "
f"stop at {self.stop_loss:.8f}. "
f"trailing stop loss saved us: "
f"{float(self.stop_loss) - float(self.initial_stop_loss):.8f} "
f"and max observed rate was {self.max_rate:.8f}")
f"{self.pair} - Stoploss adjusted. current_price={current_price:.8f}, "
f"open_rate={self.open_rate:.8f}, max_rate={self.max_rate:.8f}, "
f"initial_stop_loss={self.initial_stop_loss:.8f}, "
f"stop_loss={self.stop_loss:.8f}. "
f"Trailing stoploss saved us: "
f"{float(self.stop_loss) - float(self.initial_stop_loss):.8f}.")
def update(self, order: Dict) -> None:
"""
@ -331,24 +330,19 @@ class Trade(_DECL_BASE):
self
)
def calc_open_trade_price(
self,
fee: Optional[float] = None) -> float:
def calc_open_trade_price(self, fee: Optional[float] = None) -> float:
"""
Calculate the open_rate including fee.
:param fee: fee to use on the open rate (optional).
If rate is not set self.fee will be used
:return: Price in of the open trade incl. Fees
"""
buy_trade = (Decimal(self.amount) * Decimal(self.open_rate))
fees = buy_trade * Decimal(fee or self.fee_open)
return float(buy_trade + fees)
def calc_close_trade_price(
self,
rate: Optional[float] = None,
fee: Optional[float] = None) -> float:
def calc_close_trade_price(self, rate: Optional[float] = None,
fee: Optional[float] = None) -> float:
"""
Calculate the close_rate including fee
:param fee: fee to use on the close rate (optional).
@ -357,7 +351,6 @@ class Trade(_DECL_BASE):
If rate is not set self.close_rate will be used
:return: Price in BTC of the open trade
"""
if rate is None and not self.close_rate:
return 0.0
@ -365,10 +358,8 @@ class Trade(_DECL_BASE):
fees = sell_trade * Decimal(fee or self.fee_close)
return float(sell_trade - fees)
def calc_profit(
self,
rate: Optional[float] = None,
fee: Optional[float] = None) -> float:
def calc_profit(self, rate: Optional[float] = None,
fee: Optional[float] = None) -> float:
"""
Calculate the absolute profit in stake currency between Close and Open trade
:param fee: fee to use on the close rate (optional).
@ -385,10 +376,8 @@ class Trade(_DECL_BASE):
profit = close_trade_price - open_trade_price
return float(f"{profit:.8f}")
def calc_profit_percent(
self,
rate: Optional[float] = None,
fee: Optional[float] = None) -> float:
def calc_profit_percent(self, rate: Optional[float] = None,
fee: Optional[float] = None) -> float:
"""
Calculates the profit in percentage (including fee).
:param rate: rate to compare with (optional).
@ -396,7 +385,6 @@ class Trade(_DECL_BASE):
:param fee: fee to use on the close rate (optional).
:return: profit in percentage as float
"""
open_trade_price = self.calc_open_trade_price()
close_trade_price = self.calc_close_trade_price(
rate=(rate or self.close_rate),
@ -436,8 +424,8 @@ class Trade(_DECL_BASE):
and trade.initial_stop_loss_pct != desired_stoploss):
# Stoploss value got changed
logger.info(f"Stoploss for {trade} needs adjustment.")
logger.info(f"Stoploss for {trade} needs adjustment...")
# Force reset of stoploss
trade.stop_loss = None
trade.adjust_stop_loss(trade.open_rate, desired_stoploss)
logger.info(f"new stoploss: {trade.stop_loss}, ")
logger.info(f"New stoploss: {trade.stop_loss}.")

40
freqtrade/strategy/interface.py
View File

@ -202,7 +202,6 @@ class IStrategy(ABC):
:param metadata: Metadata dictionary with additional data (e.g. 'pair')
:return: DataFrame with ticker data and indicator data
"""
pair = str(metadata.get('pair'))
# Test if seen this pair and last candle before.
@ -292,7 +291,6 @@ class IStrategy(ABC):
:param force_stoploss: Externally provided stoploss
:return: True if trade should be sold, False otherwise
"""
# Set current rate to low for backtesting sell
current_rate = low or rate
current_profit = trade.calc_profit_percent(current_rate)
@ -304,6 +302,8 @@ class IStrategy(ABC):
force_stoploss=force_stoploss, high=high)
if stoplossflag.sell_flag:
logger.debug(f"{trade.pair} - Stoploss hit. sell_flag=True, "
f"sell_type={stoplossflag.sell_type}")
return stoplossflag
# Set current rate to high for backtesting sell
@ -312,22 +312,31 @@ class IStrategy(ABC):
experimental = self.config.get('experimental', {})
if buy and experimental.get('ignore_roi_if_buy_signal', False):
logger.debug('Buy signal still active - not selling.')
# This one is noisy, commented out
# logger.debug(f"{trade.pair} - Buy signal still active. sell_flag=False")
return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE)
# Check if minimal roi has been reached and no longer in buy conditions (avoiding a fee)
if self.min_roi_reached(trade=trade, current_profit=current_profit, current_time=date):
logger.debug('Required profit reached. Selling..')
logger.debug(f"{trade.pair} - Required profit reached. sell_flag=True, "
f"sell_type=SellType.ROI")
return SellCheckTuple(sell_flag=True, sell_type=SellType.ROI)
if experimental.get('sell_profit_only', False):
logger.debug('Checking if trade is profitable..')
# This one is noisy, commented out
# logger.debug(f"{trade.pair} - Checking if trade is profitable...")
if trade.calc_profit(rate=rate) <= 0:
# This one is noisy, commented out
# logger.debug(f"{trade.pair} - Trade is not profitable. sell_flag=False")
return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE)
if sell and not buy and experimental.get('use_sell_signal', False):
logger.debug('Sell signal received. Selling..')
logger.debug(f"{trade.pair} - Sell signal received. sell_flag=True, "
f"sell_type=SellType.SELL_SIGNAL")
return SellCheckTuple(sell_flag=True, sell_type=SellType.SELL_SIGNAL)
# This one is noisy, commented out...
# logger.debug(f"{trade.pair} - No sell signal. sell_flag=False")
return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE)
def stop_loss_reached(self, current_rate: float, trade: Trade,
@ -338,7 +347,6 @@ class IStrategy(ABC):
decides to sell or not
:param current_profit: current profit in percent
"""
trailing_stop = self.config.get('trailing_stop', False)
stop_loss_value = force_stoploss if force_stoploss else self.stoploss
@ -359,7 +367,7 @@ class IStrategy(ABC):
if 'trailing_stop_positive' in self.config and high_profit > sl_offset:
# Ignore mypy error check in configuration that this is a float
stop_loss_value = self.config.get('trailing_stop_positive') # type: ignore
logger.debug(f"using positive stop loss: {stop_loss_value} "
logger.debug(f"{trade.pair} - Using positive stoploss: {stop_loss_value} "
f"offset: {sl_offset:.4g} profit: {current_profit:.4f}%")
trade.adjust_stop_loss(high or current_rate, stop_loss_value)
@ -369,20 +377,20 @@ class IStrategy(ABC):
(trade.stop_loss >= current_rate) and
(not self.order_types.get('stoploss_on_exchange'))):
selltype = SellType.STOP_LOSS
sell_type = SellType.STOP_LOSS
# If initial stoploss is not the same as current one then it is trailing.
if trade.initial_stop_loss != trade.stop_loss:
selltype = SellType.TRAILING_STOP_LOSS
sell_type = SellType.TRAILING_STOP_LOSS
logger.debug(
f"HIT STOP: current price at {current_rate:.6f}, "
f"stop loss is {trade.stop_loss:.6f}, "
f"initial stop loss was at {trade.initial_stop_loss:.6f}, "
f"{trade.pair} - HIT STOP: current price at {current_rate:.6f}, "
f"stoploss is {trade.stop_loss:.6f}, "
f"initial stoploss was at {trade.initial_stop_loss:.6f}, "
f"trade opened at {trade.open_rate:.6f}")
logger.debug(f"trailing stop saved {trade.stop_loss - trade.initial_stop_loss:.6f}")
logger.debug(f"{trade.pair} - Trailing stop saved "
f"{trade.stop_loss - trade.initial_stop_loss:.6f}")
logger.debug('Stop loss hit.')
return SellCheckTuple(sell_flag=True, sell_type=selltype)
return SellCheckTuple(sell_flag=True, sell_type=sell_type)
return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE)

56
tests/test_freqtradebot.py
View File

@ -1590,6 +1590,8 @@ def test_update_trade_state(mocker, default_conf, limit_buy_order, caplog) -> No
Trade.session = MagicMock()
trade.open_order_id = '123'
trade.open_fee = 0.001
# Add datetime explicitly since sqlalchemy defaults apply only once written to database
trade.open_date = arrow.utcnow().datetime
freqtrade.update_trade_state(trade)
# Test amount not modified by fee-logic
assert not log_has_re(r'Applying fee to .*', caplog)
@ -1823,7 +1825,8 @@ def test_handle_trade_roi(default_conf, ticker, limit_buy_order,
# if ROI is reached we must sell
patch_get_signal(freqtrade, value=(False, True))
assert freqtrade.handle_trade(trade)
assert log_has('Required profit reached. Selling..', caplog)
assert log_has("ETH/BTC - Required profit reached. sell_flag=True, sell_type=SellType.ROI",
caplog)
def test_handle_trade_experimental(
@ -1853,7 +1856,8 @@ def test_handle_trade_experimental(
patch_get_signal(freqtrade, value=(False, True))
assert freqtrade.handle_trade(trade)
assert log_has('Sell signal received. Selling..', caplog)
assert log_has("ETH/BTC - Sell signal received. sell_flag=True, sell_type=SellType.SELL_SIGNAL",
caplog)
def test_close_trade(default_conf, ticker, limit_buy_order, limit_sell_order,
@ -2132,6 +2136,7 @@ def test_check_handle_timedout_exception(default_conf, ticker, mocker, caplog) -
)
freqtrade = FreqtradeBot(default_conf)
open_date = arrow.utcnow().shift(minutes=-601)
trade_buy = Trade(
pair='ETH/BTC',
open_rate=0.00001099,
@ -2141,16 +2146,18 @@ def test_check_handle_timedout_exception(default_conf, ticker, mocker, caplog) -
fee_open=0.0,
fee_close=0.0,
stake_amount=1,
open_date=arrow.utcnow().shift(minutes=-601).datetime,
open_date=open_date.datetime,
is_open=True
)
Trade.session.add(trade_buy)
freqtrade.check_handle_timedout()
assert log_has_re(r'Cannot query order for Trade\(id=1, pair=ETH/BTC, amount=90.99181073, '
r'open_rate=0.00001099, open_since=10 hours ago\) due to Traceback \(most '
r'recent call last\):\n.*', caplog)
assert log_has_re(r"Cannot query order for Trade\(id=1, pair=ETH/BTC, amount=90.99181073, "
r"open_rate=0.00001099, open_since="
f"{open_date.strftime('%Y-%m-%d %H:%M:%S')}"
r"\) due to Traceback \(most recent call last\):\n*",
caplog)
def test_handle_timedout_limit_buy(mocker, default_conf) -> None:
@ -2793,8 +2800,9 @@ def test_trailing_stop_loss(default_conf, limit_buy_order, fee, markets, caplog,
# Sell as trailing-stop is reached
assert freqtrade.handle_trade(trade) is True
assert log_has(
f'HIT STOP: current price at 0.000012, stop loss is 0.000015, '
f'initial stop loss was at 0.000010, trade opened at 0.000011', caplog)
f"ETH/BTC - HIT STOP: current price at 0.000012, "
f"stoploss is 0.000015, "
f"initial stoploss was at 0.000010, trade opened at 0.000011", caplog)
assert trade.sell_reason == SellType.TRAILING_STOP_LOSS.value
@ -2836,8 +2844,8 @@ def test_trailing_stop_loss_positive(default_conf, limit_buy_order, fee, markets
}))
# stop-loss not reached, adjusted stoploss
assert freqtrade.handle_trade(trade) is False
assert log_has(f'using positive stop loss: 0.01 offset: 0 profit: 0.2666%', caplog)
assert log_has(f'adjusted stop loss', caplog)
assert log_has(f"ETH/BTC - Using positive stoploss: 0.01 offset: 0 profit: 0.2666%", caplog)
assert log_has(f"ETH/BTC - Adjusting stoploss...", caplog)
assert trade.stop_loss == 0.0000138501
mocker.patch('freqtrade.exchange.Exchange.get_ticker',
@ -2849,9 +2857,9 @@ def test_trailing_stop_loss_positive(default_conf, limit_buy_order, fee, markets
# Lower price again (but still positive)
assert freqtrade.handle_trade(trade) is True
assert log_has(
f'HIT STOP: current price at {buy_price + 0.000002:.6f}, '
f'stop loss is {trade.stop_loss:.6f}, '
f'initial stop loss was at 0.000010, trade opened at 0.000011', caplog)
f"ETH/BTC - HIT STOP: current price at {buy_price + 0.000002:.6f}, "
f"stoploss is {trade.stop_loss:.6f}, "
f"initial stoploss was at 0.000010, trade opened at 0.000011", caplog)
def test_trailing_stop_loss_offset(default_conf, limit_buy_order, fee,
@ -2894,8 +2902,9 @@ def test_trailing_stop_loss_offset(default_conf, limit_buy_order, fee,
}))
# stop-loss not reached, adjusted stoploss
assert freqtrade.handle_trade(trade) is False
assert log_has(f'using positive stop loss: 0.01 offset: 0.011 profit: 0.2666%', caplog)
assert log_has(f'adjusted stop loss', caplog)
assert log_has(f"ETH/BTC - Using positive stoploss: 0.01 offset: 0.011 profit: 0.2666%",
caplog)
assert log_has(f"ETH/BTC - Adjusting stoploss...", caplog)
assert trade.stop_loss == 0.0000138501
mocker.patch('freqtrade.exchange.Exchange.get_ticker',
@ -2907,9 +2916,9 @@ def test_trailing_stop_loss_offset(default_conf, limit_buy_order, fee,
# Lower price again (but still positive)
assert freqtrade.handle_trade(trade) is True
assert log_has(
f'HIT STOP: current price at {buy_price + 0.000002:.6f}, '
f'stop loss is {trade.stop_loss:.6f}, '
f'initial stop loss was at 0.000010, trade opened at 0.000011', caplog)
f"ETH/BTC - HIT STOP: current price at {buy_price + 0.000002:.6f}, "
f"stoploss is {trade.stop_loss:.6f}, "
f"initial stoploss was at 0.000010, trade opened at 0.000011", caplog)
assert trade.sell_reason == SellType.TRAILING_STOP_LOSS.value
@ -2960,7 +2969,7 @@ def test_tsl_only_offset_reached(default_conf, limit_buy_order, fee,
# stop-loss should not be adjusted as offset is not reached yet
assert freqtrade.handle_trade(trade) is False
assert not log_has(f'adjusted stop loss', caplog)
assert not log_has(f"ETH/BTC - Adjusting stoploss...", caplog)
assert trade.stop_loss == 0.0000098910
# price rises above the offset (rises 12% when the offset is 5.5%)
@ -2972,8 +2981,9 @@ def test_tsl_only_offset_reached(default_conf, limit_buy_order, fee,
}))
assert freqtrade.handle_trade(trade) is False
assert log_has(f'using positive stop loss: 0.05 offset: 0.055 profit: 0.1218%', caplog)
assert log_has(f'adjusted stop loss', caplog)
assert log_has(f"ETH/BTC - Using positive stoploss: 0.05 offset: 0.055 profit: 0.1218%",
caplog)
assert log_has(f"ETH/BTC - Adjusting stoploss...", caplog)
assert trade.stop_loss == 0.0000117705
@ -3342,8 +3352,8 @@ def test_order_book_bid_strategy2(mocker, default_conf, order_book_l2, markets)
default_conf['telegram']['enabled'] = False
freqtrade = FreqtradeBot(default_conf)
# ordrebook shall be used even if tickers would be lower.
assert freqtrade.get_target_bid('ETH/BTC', ) != 0.042
# orderbook shall be used even if tickers would be lower.
assert freqtrade.get_target_bid('ETH/BTC') != 0.042
assert ticker_mock.call_count == 0