BT finishing earlier than it should

New comment
 

I noticed this behavior start once I restarted MT5. I don't think there was any updates when it restarted. I'm currently running MT5 Build 4831.


Context: 

My EA will place a buy order every time the previous candle closed below the lower Bollinger band. So when there is a new bar I check if the previous candle close is below the Lower BB and if so, place an order. Well, ever since I restarted MT5 it will place one order in the first 10 minutes of session and then close the order due to end of test. 


The interesting part is that when running the BT in visual mode, it will place all the orders, as it should. However, in non-visual mode, it won't. It'll place just one and finish the test at that exact time, as if the trading session had ended. 


I should also mention that sometimes, it will just run the BT in non-visual mode just fine but most of the times it will finish it earlier. 


This is the "broken" BT that finishes earlier:

RP      0       05:41:00.267    Tester  "MyEA\long\MyEA-long.ex5" 64 bit
PD      0       05:41:00.850    Core 1  connecting to 127.0.0.1:3000
QQ      0       05:41:00.859    Core 1  connected
DK      0       05:41:00.865    Core 1  authorized (agent build 4831)
CQ      0       05:41:00.871    Tester  Bra50,M5 (ActivTradesCorp-Server): testing of Experts\MyEA\long\MyEA-long.ex5 from 2024.12.12 00:00 to 2024.12.13 00:00
FQ      0       05:41:00.891    Core 1  common synchronization completed
HH      3       05:41:00.891    Tester  Bra50: custom settings for the symbol applied from file 'MQL5\Profiles\Tester\Symbols\Bra50.txt'
RG      3       05:41:00.892    History nothing to analyze
IS      0       05:41:00.961    Core 1  test Experts\MyEA\long\MyEA-long.ex5 on Bra50,M5 thread finished
FF      0       05:41:00.961    Core 1  prepare for shutdown
LR      0       05:41:00.961    Core 1  shutdown finished
DM      0       05:41:00.961    Core 1  login (build 4831)
RI      0       05:41:00.961    Core 1  account info found with currency USD
NN      0       05:41:00.961    Core 1  44740 bytes of input parameters loaded
OH      0       05:41:00.961    Core 1  initial deposit 10000.00 USD, leverage 1:200
IQ      0       05:41:00.961    Core 1  successfully initialized
GF      0       05:41:00.961    Core 1  2709 bytes of total initialization data received
PS      0       05:41:00.961    Core 1  Intel Xeon  @ 2.20GHz, 16380 MB
LI      0       05:41:00.961    Core 1  Bra50: symbol to be synchronized
NL      0       05:41:00.961    Core 1  Bra50: symbol synchronized, 3880 bytes of symbol info received
HI      0       05:41:00.961    Core 1  Bra50,M5: history cached from 2023.01.02 13:00
QK      0       05:41:00.961    Core 1  Bra50,M5 (ActivTradesCorp-Server): every tick generating
OS      0       05:41:00.961    Core 1  Bra50,M5: testing of Experts\MyEA\long\MyEA-long.ex5 from 2024.12.12 00:00 to 2024.12.13 00:00 started with inputs:
MM      0       05:41:00.961    Core 1    =
FD      0       05:41:00.961    Core 1    inpInvestingProfile=2
HJ      0       05:41:00.961    Core 1    inpInvestingProfileBalancePct=100
QO      0       05:41:00.961    Core 1    =
LF      0       05:41:00.961    Core 1    inpLong=true
GJ      0       05:41:00.961    Core 1    inpEAName=
OO      0       05:41:00.961    Core 1    inpMagicNumberLong=1000
EJ      0       05:41:00.961    Core 1    inpTMF=0
LH      0       05:41:00.961    Core 1    inpMainSettingsFromProfile=false
JN      0       05:41:00.961    Core 1    inpInitialTakeProfit=5
RK      0       05:41:00.961    Core 1    inpAvgPriceTakeProfit=80
JO      0       05:41:00.961    Core 1    InpLongLot=0.05
QF      0       05:41:00.961    Core 1    InpLongStopAtDD=0
JK      0       05:41:00.961    Core 1    InpLongResumeAfterXDays=2
...
IP      0       05:41:00.961    Core 1  2024.12.12 13:00:00   2024.12.12 13:00:00 - It's a new dawn, It's a new day, It's a new life for me, ooh, And I'm feeling good
KS      0       05:41:00.961    Core 1  2024.12.12 13:10:00   2024.12.12 13:10:00 trading_actions.mq5:newOrder DEBUG: Will place a buy order now with lot size: 0.05, symbol: Bra50 at market price, with SL: 0.00, TP: 129670.00 and comment: MyEA -  - long - M5 
DS      0       05:41:00.961    Core 1  USDBRL: symbol to be synchronized
CH      0       05:41:00.961    Core 1  USDBRL: symbol synchronized already, 18 bytes received
JN      0       05:41:00.961    Core 1  2024.12.12 13:10:00   market buy 0.05 Bra50 tp: 129670 (129090 / 129105 / 129090)
LQ      0       05:41:00.961    Core 1  2024.12.12 13:10:00   deal #2 buy 0.05 Bra50 at 129105 done (based on order #2)
PK      0       05:41:00.961    Core 1  2024.12.12 13:10:00   deal performed [#2 buy 0.05 Bra50 at 129105]
NG      0       05:41:00.961    Core 1  2024.12.12 13:10:00   order performed buy 0.05 at 129105 [#2 buy 0.05 Bra50 at 129105]
CD      0       05:41:00.961    Core 1  2024.12.12 13:10:00   CTrade::OrderSend: market buy 0.05 Bra50 tp: 129670 [done at 129105]
QM      0       05:41:00.961    Core 1  2024.12.12 13:10:00   position closed due end of test at 129090 [#2 buy 0.05 Bra50 129105 tp: 129670]
IS      0       05:41:00.961    Core 1  2024.12.12 13:10:00   deal #3 sell 0.05 Bra50 at 129090 done (based on order #3)
HN      0       05:41:00.961    Core 1  2024.12.12 13:10:00   deal performed [#3 sell 0.05 Bra50 at 129090]
KM      0       05:41:00.961    Core 1  2024.12.12 13:10:00   order performed sell 0.05 at 129090 [#3 sell 0.05 Bra50 at 129090]
QJ      0       05:41:00.961    Core 1  2024.12.12 13:10:00   End of Test - DD Breakdown by buckets:
LK      0       05:41:00.961    Core 1  2024.12.12 13:10:00   0%-9%=0
LP      0       05:41:00.961    Core 1  2024.12.12 13:10:00   10%-19%=0
HI      0       05:41:00.961    Core 1  2024.12.12 13:10:00   20%-29%=0
DF      0       05:41:00.961    Core 1  2024.12.12 13:10:00   30%-39%=0
PN      0       05:41:00.961    Core 1  2024.12.12 13:10:00   40%-49%=0
LG      0       05:41:00.961    Core 1  2024.12.12 13:10:00   50%-59%=0
HL      0       05:41:00.961    Core 1  2024.12.12 13:10:00   60%-69%=0
DE      0       05:41:00.961    Core 1  2024.12.12 13:10:00   70%-79%=0
PM      0       05:41:00.961    Core 1  2024.12.12 13:10:00   80%-89%=0
LJ      0       05:41:00.961    Core 1  2024.12.12 13:10:00   90%-99%=0
QR      0       05:41:00.961    Core 1  2024.12.12 13:10:00   100%+=0
QF      0       05:41:00.961    Core 1  2024.12.12 13:10:00   DDs accounted for: 0
PQ      0       05:41:00.961    Core 1  2024.12.12 13:10:00   Profit: -0.03(-0.00%)
FE      0       05:41:00.961    Core 1  2024.12.12 13:10:00   Max DD: 0.03(0.00%)
IQ      0       05:41:00.961    Core 1  2024.12.12 13:10:00   Long Trades: 1
PF      0       05:41:00.961    Core 1  2024.12.12 13:10:00   Short Trades: 0
IR      0       05:41:00.961    Core 1  2024.12.12 13:10:00   Minimum Margin Level: 684929.45%
PJ      0       05:41:00.961    Core 1  final balance 9999.97 USD
ER      0       05:41:00.961    Core 1  OnTester result 0.03000000000065484
KG      0       05:41:00.961    Core 1  2024.12.12 13:10:00   2024.12.12 13:10:00 - MyEA has been removed from Bra50 with timeframe M5
KI      0       05:41:00.961    Core 1  2024.12.12 13:10:00   In Backtesting mode so won't actually be sending push notification with message: (v.2025Mar25) - Bra50
II      0       05:41:00.961    Core 1  2024.12.12 13:10:00   MyEA has been removed from Bra50 with timeframe M5
HE      0       05:41:00.961    Core 1  2024.12.12 13:10:00   Message ID: 30644
HL      0       05:41:00.961    Core 1  Bra50,M5: 3619 ticks, 3 bars generated. Environment synchronized in 0:00:00.027. Test passed in 0:00:00.069.
PL      0       05:41:00.961    Core 1  Bra50,M5: total time from login to stop testing 0:00:00.096 (including 0:00:00.027 for history data synchronization)
FR      0       05:41:00.961    Core 1  4711 total ticks for all symbols
HF      0       05:41:00.961    Core 1  Bra50: passed to tester 92742 ticks
MR      0       05:41:00.961    Core 1  USDBRL: passed to tester 90640 ticks
PD      0       05:41:00.961    Core 1  84 Mb memory used including 3 Mb of history data, 64 Mb of tick data
II      0       05:41:00.961    Core 1  log file "C:\Users\user\AppData\Roaming\MetaQuotes\Tester\D0E8209F77C8CF37AD8BF550E51FF075\Agent-127.0.0.1-3000\logs\20250402.log" written
JD      0       05:41:01.353    Core 1  connection closed



You can see in the example where it ends prematurely that it says only 3 bars were generated. 


I deleted all the cache under `Tester\cache` and all the data under `bases` but it hasn't fixed the issue. 


Running with every tick based on real ticks seems to resolve but I'm not sure as the results vary. Some times it runs fine, sometimes it will finish earlier it seems completely random. 


Please don't question the validity of the code, this EA is older than 1 year and I run backtests pretty much every week and only now I noticed this behavior. Also, we can clearly see the tests finishing off earlier than it should, my EA couldn't possibly cause that. If you have no clue and nothing to add your silence is appreciated.

 

Looking at the last screenshot: "history cache allowed for 54260 bars and contains 54040 bars from 2023.01.02 13:00 to 2024.12.11 22:20"

You're trying to test from 2024.12.12 to 2024.12.13 and have no history loaded for that time.

Visual mode works as that basically runs like "every tick based on real ticks" which is what you should always be using anyway. "every tick" in MetaTrader is just OHLC and then it makes up the ticks, while "every tick based on real ticks" gets actual market data and uses that. Reference: Tick Data Explained. Remember MT4 is from 2005 and MT5 is from 2010, back in those days' shortcuts had to be taken if you didn't want the back test to take hours and literal days if you wanted to optimize something. These days you should always use "every tick based on real ticks".

 
thanks for your input James. i know the difference and I've actually noticed some significant differences in every tick vs every tick based on real ticks. Regardless, this behavior tells me there is something wrong with MT or the data it's using. While I'll probably stick to using real ticks in my tests, I just wanted to let people know of this possible issue and I was also hoping someone would be able to spot something that would explain this. Thanks anyway. 
New comment