Разное

Особенности исполнения торговых приказов MT5

6 февраля 2020, 01:47
fxsaber
fxsaber
13
413

Анализировал с владельцем MT5-сервера тормоза торговых приказов. Запускался OrderSend-Test2.mq5 в том же месте, где MT5-сервер стоит. Т.е. нулевой пинг. Демо, все внутри.

Изучались логи MT5-сервера (2170) и MT5-клиента (2280). Логи сервера не буду приводить, просто словами опишу.


Думаю, результаты буду интерсны всем, т.к. это поможет раскрыть возможные причины тормозов, часто упоминаемых на форуме.


Особенность 1.

Маркет-ордер на закрытие позиции.

DF      0       20:13:56.950    Trades  '': market sell 0.01 EURUSD, close #243731 buy 0.01 EURUSD 1.09978
PI      0       20:13:56.951    Trades  '': accepted market sell 0.01 EURUSD, close #243731 buy 0.01 EURUSD 1.09978
CK      0       20:13:56.951    Trades  '': deal #72281 sell 0.01 EURUSD at 1.09975 done (based on order #243732)
KR      0       20:13:56.958    Trades  '': order #243732 sell 0.01 / 0.01 EURUSD at 1.09975 done in 8.437 ms

Из лога Терминала видно, что 8 мс (многовато на самом деле). Однако, из лога советника, где засекалось выполнение синхронного OrderSend несколько иное значение.

DM      0       20:13:57.059    Alert: EURUSD 243732 Request executed 109.676 + 0.015 (0) ms.
JQ      0       20:13:57.059    Request.action = TRADE_ACTION_DEAL (1)
KF      0       20:13:57.059    Request.magic = 0
DM      0       20:13:57.059    Request.order = 0
FI      0       20:13:57.059    Request.symbol = EURUSD
KG      0       20:13:57.059    Request.volume = 0.01
PS      0       20:13:57.059    Request.price = 1.09975
GI      0       20:13:57.059    Request.stoplimit = 0.0
NQ      0       20:13:57.059    Request.sl = 1.10975
NI      0       20:13:57.059    Request.tp = 0.0
NN      0       20:13:57.059    Request.deviation = 100
NE      0       20:13:57.059    Request.type = ORDER_TYPE_SELL (1)
PK      0       20:13:57.059    Request.type_filling = ORDER_FILLING_FOK (0)
HL      0       20:13:57.060    Request.type_time = ORDER_TIME_GTC (0)
PM      0       20:13:57.060    Request.expiration = 1970.01.01 00:00:00
CG      0       20:13:57.060    Request.comment = OrderSendTest_Position
CG      0       20:13:57.060    Request.position = 243731
QQ      0       20:13:57.060    Request.position_by = 0
JG      0       20:13:57.060    Result.retcode = 10009
RN      0       20:13:57.060    Result.deal = 72281
QJ      0       20:13:57.060    Result.order = 243732
MN      0       20:13:57.060    Result.volume = 0.01
PJ      0       20:13:57.060    Result.price = 1.09975
NE      0       20:13:57.060    Result.bid = 1.09975
CM      0       20:13:57.060    Result.ask = 1.09978
DJ      0       20:13:57.060    Result.comment = Request executed 109.676 + 0.015 (0) ms.
CH      0       20:13:57.060    Result.request_id = 20471
LR      0       20:13:57.060    Result.retcode_external = 0

Т.е. на 100 мс больше. Причина в такой работе OrderSend:

  1. Отправляется ордер.
  2. Приходит ответ, что исполнился.
  3. Ждем синхронизации истории торгов с тем, что есть.
  4. Выходим.

Ожидание третьего шага - 100 мс. Т.е. Вы могли через 8 мс получить ответ, что ордер исполнен. Но только через 100 мс история торгов была бы синхронизирована. И штатная OrderSend ждала эти 100 мс.

Ну либо какая-то другая причина. Но она точно внутри штатной OrderSend.


А теперь вернемся к 8 мс, что показывает MT5-клиент, получая OnTradeTransaction-события. На MT5-сервере исполнение было меньше 1 мс (по логам 0.76 ms). Т.е. тормозит сам MT5-клиент!


Особенность 2.

Открытие позиции маркет-ордером.

EO      0       20:13:10.608    Trades  '': market buy 0.01 USDCHF
OF      0       20:13:10.702    Trades  '': accepted market buy 0.01 USDCHF
NM      0       20:13:10.702    Trades  '': deal #68466 buy 0.01 USDCHF at 0.97360 done (based on order #236103)
RE      0       20:13:10.703    Trades  '': order #236103 buy 0.01 / 0.01 USDCHF at 0.97360 done in 94.964 ms

95 мс. Обратите внимание, что это время было потрачено до второй строки (accepted). На сервере было исполнение меньше 1 мс. Т.е. это тормоза самого MT5-клиента, никак не связанные с MT5-сервером.


Штатная OrderSend отработала без доп. тормозов.

PK      0       20:13:10.703    Alert: USDCHF 236103 Request executed 95.033 + 0.010 (0) ms.
IL      0       20:13:10.703    Request.action = TRADE_ACTION_DEAL (1)
LQ      0       20:13:10.703    Request.magic = 0
OI      0       20:13:10.703    Request.order = 0
PM      0       20:13:10.703    Request.symbol = USDCHF
HK      0       20:13:10.703    Request.volume = 0.01
GO      0       20:13:10.703    Request.price = 0.9736
NE      0       20:13:10.703    Request.stoplimit = 0.0
JE      0       20:13:10.703    Request.sl = 0.0
GM      0       20:13:10.703    Request.tp = 0.0
GJ      0       20:13:10.703    Request.deviation = 100
PL      0       20:13:10.703    Request.type = ORDER_TYPE_BUY (0)
OD      0       20:13:10.703    Request.type_filling = ORDER_FILLING_FOK (0)
QK      0       20:13:10.703    Request.type_time = ORDER_TIME_GTC (0)
IP      0       20:13:10.703    Request.expiration = 1970.01.01 00:00:00
NS      0       20:13:10.703    Request.comment = OrderSendTest_Position
NG      0       20:13:10.703    Request.position = 0
RL      0       20:13:10.703    Request.position_by = 0
IJ      0       20:13:10.703    Result.retcode = 10009
MM      0       20:13:10.703    Result.deal = 68466
LO      0       20:13:10.703    Result.order = 236103
NI      0       20:13:10.703    Result.volume = 0.01
GL      0       20:13:10.703    Result.price = 0.9736
FF      0       20:13:10.703    Result.bid = 0.97354
ES      0       20:13:10.703    Result.ask = 0.9736
EF      0       20:13:10.703    Result.comment = Request executed 95.033 + 0.010 (0) ms.
FH      0       20:13:10.703    Result.request_id = 7120
CL      0       20:13:10.703    Result.retcode_external = 0


Обновился клиент (2314) и сервер (2314).


Особенность 3.

GF  0  22:48:11.209  Trades  '': market sell 0.01 GBPAUD, close #296371 buy 0.01 GBPAUD 1.92667
LH  0  22:48:11.210  Trades  '': accepted market sell 0.01 GBPAUD, close #296371 buy 0.01 GBPAUD 1.92667
EK  0  22:48:11.211  Trades  '': deal #98601 sell 0.01 GBPAUD at 1.92590 done (based on order #296372)
IQ  0  22:48:11.227  Trades  '': order #296372 sell 0.01 / 0.01 GBPAUD at 1.92590 done in 17.974 ms

Здесь уже 17 мс, а на сервере 0.68 мс. При этом видно, что тормоза перед последней строкой (между deal-done и order-done).


Та же история, но более показательная

GD      0       22:58:19.529    Trades  '': market buy 0.01 USDCNH
KO      0       22:58:19.531    Trades  '': accepted market buy 0.01 USDCNH
LF      0       22:58:19.531    Trades  '': deal #105132 buy 0.01 USDCNH at 6.97570 done (based on order #309435)
LN      0       22:58:20.082    Trades  '': order #309435 buy 0.01 / 0.01 USDCNH at 6.97570 done in 554.268 ms

554 мс на клиенте и 0.95 мс на сервере.


Напоминаю, что MT5-клиент запускался на том же компе и ОС, на котором был запущен MT5-сервер. Похоже, это те самые тормоза, которые разработчики не могут годами найти.

Для их воспроизведения (за несколько секунд) разработчикам нужно просто запустить скрипт OrderSend-Test2.mq5 так же, как было здесь описано.


Особенность 4.

Теперь придется привести (что-то удалил руками) лог сервера. 
2020.02.05 22:32:12.844   '': market buy 0.01 USDCNH (6.97533 / 6.97767)
2020.02.05 22:32:12.845   '': request confirmed at market price 6.97767, rule 'Auto Execution' (market buy 0.01 USDCNH)(6.97533 / 6.97767)
2020.02.05 22:32:12.912   '': deal performed [#85468 buy 0.01 USDCNH at 6.97767]
2020.02.05 22:32:12.997   '': order performed buy 0.01 at 6.97767 [#270107 buy 0.01 USDCNH at market], time 162.13 ms

маркет-ордер внутри самого сервера исполнялся 162 мс. Владелец сервера сообщил, что правило задержки в маршрутизации отсутствует в логе (вроде, в ранних билдах присутствовала), но она точно отключена.


Лог OrderSend.

IM      0       22:32:13.395    Alert: USDCNH 270107 Request executed 560.232 + 0.056 (0) ms.
NQ      0       22:32:13.395    Request.action = TRADE_ACTION_DEAL (1)
OF      0       22:32:13.395    Request.magic = 0
LM      0       22:32:13.395    Request.order = 0
KH      0       22:32:13.395    Request.symbol = USDCNH
CG      0       22:32:13.395    Request.volume = 0.01
OS      0       22:32:13.395    Request.price = 6.97767
OH      0       22:32:13.395    Request.stoplimit = 0.0
GQ      0       22:32:13.395    Request.sl = 0.0
JH      0       22:32:13.395    Request.tp = 0.0
JN      0       22:32:13.395    Request.deviation = 100
EI      0       22:32:13.395    Request.type = ORDER_TYPE_BUY (0)
RH      0       22:32:13.395    Request.type_filling = ORDER_FILLING_FOK (0)
PO      0       22:32:13.395    Request.type_time = ORDER_TIME_GTC (0)
HL      0       22:32:13.395    Request.expiration = 1970.01.01 00:00:00
KH      0       22:32:13.395    Request.comment = OrderSendTest_Position
KS      0       22:32:13.395    Request.position = 0
OP      0       22:32:13.395    Request.position_by = 0
DE      0       22:32:13.395    Result.retcode = 10009
KP      0       22:32:13.395    Result.deal = 85468
OD      0       22:32:13.395    Result.order = 270107
GL      0       22:32:13.395    Result.volume = 0.01
QH      0       22:32:13.395    Result.price = 6.97767
FR      0       22:32:13.395    Result.bid = 6.97533
IL      0       22:32:13.395    Result.ask = 6.97767
RI      0       22:32:13.395    Result.comment = Request executed 560.232 + 0.056 (0) ms.
FN      0       22:32:13.395    Result.request_id = 1
RG      0       22:32:13.395    Result.retcode_external = 0


Скрин из истории торгов этого исполнения на клиенте.

На сервере.

В истории торгов показано, что якобы исполнение было 9 мс, а не 162 мс. Т.е. история торгов сформирована ошибочно. Даже если правильно, то 9 мс внутри себя - это очень много!


Оказалось, что имеет значение фактор "разогрева". Этот ордер запускался на холодную - клиент подключился к серверу. Лог клиента.

LP  0  22:31:28.350  Network  '': authorized on through MetaTrader 5 Access Server (ping: 0.20 ms)
CS  0  22:31:28.350  Network  '': previous successful authorization performed from on 2020.02.05 22:28:38
HR  0  22:31:28.449  Network  '': terminal synchronized with 
HO  0  22:31:28.449  Network  '': trading has been enabled - hedging mode
PH  3  22:31:28.524  HistoryBase  'EURUSD' 4 invalid bars removed
FN  0  22:31:54.954  Scripts  script OrderSend-Test2 (2) (EURUSD,H1) loaded successfully
FK  0  22:32:12.835  Trades  '': market buy 0.01 USDCNH
FR  0  22:32:12.847  Trades  '': accepted market buy 0.01 USDCNH
QJ  0  22:32:12.913  Trades  '': deal #85468 buy 0.01 USDCNH at 6.97767 done (based on order #270107)
JK  0  22:32:13.395  Trades  '': order #270107 buy 0.01 / 0.01 USDCNH at 6.97767 done in 560.098 ms


Особенность 5.

Открытие позиции руками на холодную.

Сервер.

2020.02.06 00:02:47.079  '': order performed buy 1.00 at 1.10002 [#347026 buy 1.00 EURUSD at market], time 110.52 ms


Клиент.

2020.02.06 00:02:46.969  Trades  '': market buy 1.00 EURUSD
2020.02.06 00:02:47.255  Trades  '': accepted market buy 1.00 EURUSD
2020.02.06 00:02:47.255  Trades  '': deal #123927 buy 1.00 EURUSD at 1.10002 done (based on order #347026)
2020.02.06 00:02:47.256  Trades  '': order #347026 buy 1.00 / 1.00 EURUSD at 1.10002 done in 287.775 ms


Скрин базы.


Здесь длительность исполнения в базе совпадает с логом сервера.


Особенность 6.

Для такого количества записей в истории торгов.


Простейшая работа с историей (на горячую)

#include <MT4Orders.mqh>

#define BENCH(A)                                                               \
{                                                                              \
  const ulong _StartTime = GetMicrosecondCount();                              \
  A;                                                                           \
  Print("Time[" + #A + "] = " + (string)(GetMicrosecondCount() - _StartTime)); \
}

void OnStart()
{
  BENCH(HistorySelectByPosition(270107))
  BENCH(HistorySelect(0, INT_MAX))
}

выливается в такое время.

Time[HistorySelectByPosition(270107)] = 11401
Time[HistorySelect(0,INT_MAX)] = 152189

11 мс на одну штатную (дорогую) функцию. Аккуратнее с ней. Рекомендую на определенном пороге размера базы истории торгов сменять счет, чтобы база была с нуля. Тогда не будет тормозов этих. Кстати, GUI MT5-терминала иногда ОЧЕНЬ сильно начинает тормозить при формировании таблицы столь большой базы. 150 мс на HistorySelect говорит за себя.


Ну и по времени исполнения такой скрипт.

#property description "Выводит самые длительные по времени исполнения маркет-ордера"
#property script_show_inputs

input int inOrdersAmount = 10; // Сколько ордеров показать

struct ORDER_FILL_TIME
{
private:  
  long Order;
  
  long TimeSetup;
  long TimeDone;

  string TimeToString( const long time ) const
  {
    return(::TimeToString((datetime)(time / 1000), TIME_DATE | TIME_SECONDS) + "." + ::IntegerToString(time % 1000, 3, '0'));
  }

public:  
  bool Set( const long Ticket )
  {
    const bool Res = Ticket && (HistoryOrderGetInteger(Ticket, ORDER_TYPE) <= ORDER_TYPE_SELL);
    
    if (Res)
    {
      this.Order = Ticket;
      
      this.TimeSetup = ::HistoryOrderGetInteger(this.Order, ORDER_TIME_SETUP_MSC);
      this.TimeDone = ::HistoryOrderGetInteger(this.Order, ORDER_TIME_DONE_MSC);
    }
    
    return(Res);    
  }

  int GetInterval() const
  {
    return((int)(this.TimeDone - this.TimeSetup));
  }
    
  string ToString() const
  {
    return((string)this.Order + ": " + this.TimeToString(this.TimeDone) + " - " +
                                       this.TimeToString(this.TimeSetup) + " = " +
                                       (string)(this.GetInterval()) + " ms.");
  }
};

int GetOrdersData( ORDER_FILL_TIME &Orders[] )
{
  int Amount = 0;
  
  if (HistorySelect(0, INT_MAX))
  {
    const int Size = ArrayResize(Orders, HistoryOrdersTotal());
    
    for (int i = 0; i < Size; i++)
      if (Orders[Amount].Set(HistoryOrderGetTicket(i)))
        Amount++;
  }
  
  return(ArrayResize(Orders, Amount));
}

void OnStart()
{
  ORDER_FILL_TIME OrdersFillTime[];
  int Intervals[][2];
  
  const int Size = ArrayResize(Intervals, GetOrdersData(OrdersFillTime));
  
  for (int i = 0; i < Size; i++)
  {
    Intervals[i][0] = OrdersFillTime[i].GetInterval();
    Intervals[i][1] = i;    
  }
  
  ArraySort(Intervals);
  
  const int Size2 = MathMin(Size, inOrdersAmount);

  for (int i = 0; i < Size2; i++)
    Print((string)i + ". " + OrdersFillTime[Intervals[Size - i - 1][1]].ToString());    
}


Такой результат.

0. 117183: 2020.02.05 23:21:21.321 - 2020.02.05 23:21:21.008 = 313 ms.
1. 117049: 2020.01.22 21:09:11.361 - 2020.01.22 21:09:11.231 = 130 ms.
2. 346727: 2020.02.05 23:21:10.827 - 2020.02.05 23:21:10.705 = 122 ms.
3. 117054: 2020.01.23 23:23:15.432 - 2020.01.23 23:23:15.320 = 112 ms.
4. 117156: 2020.01.30 21:26:01.311 - 2020.01.30 21:26:01.200 = 111 ms.
5. 117105: 2020.01.30 21:00:54.115 - 2020.01.30 21:00:54.004 = 111 ms.
6. 117188: 2020.02.05 23:21:21.600 - 2020.02.05 23:21:21.489 = 111 ms.
7. 117205: 2020.02.05 23:30:20.795 - 2020.02.05 23:30:20.684 = 111 ms.
8. 346418: 2020.02.05 23:18:13.550 - 2020.02.05 23:18:13.439 = 111 ms.
9. 346503: 2020.02.05 23:18:29.238 - 2020.02.05 23:18:29.127 = 111 ms.


Как минимум 313 мс один из маркет-ордеров исполнялся на стороне Сервера. Можете проверить на своих счетах скриптом этот показатель, чтобы понять, были ли проблемы с исполнением.

#MT5, Fill, OrderSend