О профилировщике кода MT5 - страница 5

Новый комментарий
 
Единственно смущает второй слип. Остальное все в силе.

Разберемся
 
Renat Fatkhullin #:
Единственно смущает второй слип. Остальное все в силе.

По всей видимости, профилировщик не годится для целей ускорить куски кода, выполняющиеся быстрее нескольких миллисекунд.

  
#include <fxsaber\Usage\Usage.mqh> // https://www.mql5.com/ru/code/33875

const bool Init = EventSetMillisecondTimer(1);

void Sleep2( uint Interval )
{
  const ulong StartTime = GetMicrosecondCount();
  
  Interval *= 1000;
  
  while (GetMicrosecondCount() - StartTime < Interval)
    ;
}

#define Sleep Sleep2

void f()
{
  Sleep(10);
}

void OnTimer()
{
  _USAGE
  
  f();
  
  Sleep(20);
}

Советник 30 мс находится в слипе, а профилировщик показыает, что аж 13% он находился в функции, где три сложения и два умножения!


А вот, что показывает b2593.

Там ноль! Потому что, действительно, там ноль. Более того, по второму отчету все предельно очевидно.


Давайте разбираться, чтобы улучшить, а не ругаться.

 
fxsaber #:

профилировщик показыает, что аж 13% он находился в функции, где три сложения и два умножения!

Вот и думал, по какой причине боевой советник, полный проход которого в OnTick занимает в среднем 3 мс (там полно расчетов и работы с торговым окружением) при профилировании якобы 60% находится в "три сложения и два умножения". Пришел вот к таким лаконичным примерам.


Хочу воспользоваться старым профилировщиком в MT5, но тут такие пляски с билдами приходится творить. До сих пор не удалось запустить.

 
fxsaber #:

Прошу помочь с интерпретацией данных профайлера на простом примере.


Все выглядит, как лютый бред.

  • Sleep(2) напрочь отсутствует.
  • По какой-то причине USAGE выжирает в несколько раз больше, чем Sleep(1).


Очень стараюсь въехать, не выходит пока.


ЗЫ Пробовал замену Sleep.

Все также непонятные значения профайлера.

Что в отчёте по вызовам?

Впечатление, что приведённый код не соответствует отчёту на скриншоте.
Точно не правили код, пока работал профилировщик ?

 
Ilyas #:

Что в отчёте по вызовам?

Впечатление, что приведённый код не соответствует отчёту на скриншоте.
Точно не правили код, пока работал профилировщик ?

Не правил.


2021.09.10 11:46:48.616 MQL5 profiler   8064 total measurements, 0/0 errors, 2014 kb of stack memory analyzed (11256/1073741824)
2021.09.10 11:46:48.616 MQL5 profiler   49442 total function frames found (9141 mql5 code, 6461 built-in, 11590 other, 22250 system)
 

Прошу помощи в расшифровке результатов профилировщика.

#include <MT4Orders.mqh> // https://www.mql5.com/ru/code/16006

void OnStart()
{   
  double Res = 0;
  const int Total = OrdersHistoryTotal();
  
  for (int i = 0; i < Total; i++)
    if (OrderSelect(i, SELECT_BY_POS, MODE_HISTORY))
      Res += OrderProfit();      
}
MQL Profiler Report - \MQL5\Experts\Test19.mq5
Function Line Total CPU Percentage Self CPU Percentage
MT4ORDERS::GetHistoryPositionData 1093 7
50.00%
2
14.29%
   MT4ORDERS::Order.CloseTimeMsc = ::HistoryDealGetInteger(Ticket, DEAL_TIME_MSC); 1109 1
12.50%
1
50.00%
   } 1360 1
12.50%
1
50.00%
   return(Ticket && ((::HistoryOrderGetInteger(Ticket, ORDER_TICKET) == Ticket) || 824 2
25.00%
0
0.00%
   WHILE(_B2(MT4ORDERS::HistorySelectOrder(OrderTicket))) // https://www.mql5.com/ru/forum/304239#comment_10710403 1151 1
12.50%
0
0.00%
   StartTime = ::GetMicrosecondCount(); 1370 1
12.50%
0
0.00%
   double OrderPriceOpen = ::HistoryOrderGetDouble(OrderTicket, ORDER_PRICE_OPEN); 1182 1
12.50%
0
0.00%
   MT4ORDERS::Order.TicketID = ::HistoryDealGetInteger(MT4ORDERS::Order.Ticket, DEAL_POSITION_ID); 1096 1
12.50%
0
0.00%
CHashMap<ulong,ulong>::Resize 514 1
7.14%
1
7.14%
   m_entries[i].next = m_buckets[bucket]; 526 1
12.50%
1
100.00%
   ArrayFill(m_buckets,0,new_size,-1); 518 7
87.50%
0
0.00%
@global_initializations 1
7.14%
1
7.14%
   class MT4HISTORY 428 1
50.00%
1
100.00%
   static const bool MT4ORDERS::IsTester = ::MQLInfoInteger(MQL_TESTER); 2496 1
50.00%
0
0.00%
MT4HISTORY::RefreshHistory 588 6
42.86%
0
0.00%
   this.Tickets[this.Amount - 1] = (long)TicketDeal; 626 2
28.57%
0
0.00%
   if (_B2(::HistorySelect(0, INT_MAX))) 590 3
42.86%
0
0.00%
   ::HistoryDealGetInteger((TicketDeal = ::HistoryDealGetTicket(this.LastTotalDeals)), DEAL_TIME_MSC) : LONG_MAX; 636 1
14.29%
0
0.00%
   return(!::HistoryOrderGetInteger(Ticket, ORDER_POSITION_ID) || (::HistoryOrderGetDouble(Ticket, ORDER_VOLUME_CURRENT) && 660 1
14.29%
0
0.00%
CHashMap<ulong,ulong>::Add 294 1
7.14%
0
0.00%
   Resize(new_size); 600 1
50.00%
0
0.00%
   if((candidate%divisor)==0) 40 1
50.00%
0
0.00%
OnStart 3 13
92.86%
0
0.00%
   _B2(this.RefreshHistory()); 763 6
40.00%
0
0.00%
   _BV2(MT4ORDERS::GetHistoryPositionData(Ticket)) 1872 7
46.67%
0
0.00%
   return(_B2(MT4ORDERS::MT4OrderSelect(Index, Select, Pool))); 2588 2
13.33%
0
0.00%



MQL Profiler Report - \MQL5\Experts\Test19.mq5
Function Line Total CPU Percentage Self CPU Percentage
HistoryOrderGetInteger 3
21.43%
3
21.43%
   WHILE(_B2(MT4ORDERS::HistorySelectOrder(OrderTicket))) // https://www.mql5.com/ru/forum/304239#comment_10710403 1151 1
7.14%
3
21.43%
   return(Ticket && ((::HistoryOrderGetInteger(Ticket, ORDER_TICKET) == Ticket) || 824 2
14.29%
3
21.43%
HistorySelect 3
21.43%
3
21.43%
   if (_B2(::HistorySelect(0, INT_MAX))) 590 3
21.43%
3
21.43%
HistoryOrderGetDouble 2
14.29%
2
14.29%
   double OrderPriceOpen = ::HistoryOrderGetDouble(OrderTicket, ORDER_PRICE_OPEN); 1182 1
7.14%
2
14.29%
   return(!::HistoryOrderGetInteger(Ticket, ORDER_POSITION_ID) || (::HistoryOrderGetDouble(Ticket, ORDER_VOLUME_CURRENT) && 660 1
7.14%
2
14.29%
MT4ORDERS::GetHistoryPositionData 1093 7
50.00%
2
14.29%
   _BV2(MT4ORDERS::GetHistoryPositionData(Ticket)) 1872 7
50.00%
2
14.29%
GetMicrosecondCount 1
7.14%
1
7.14%
   StartTime = ::GetMicrosecondCount(); 1370 1
7.14%
1
7.14%
CHashMap<ulong,ulong>::Resize 514 1
7.14%
1
7.14%
   Resize(new_size); 600 1
7.14%
1
7.14%
HistoryDealGetInteger 1
7.14%
1
7.14%
   ::HistoryDealGetInteger((TicketDeal = ::HistoryDealGetTicket(this.LastTotalDeals)), DEAL_TIME_MSC) : LONG_MAX; 636 1
7.14%
1
7.14%
@global_initializations 1
7.14%
1
7.14%
CHashMap<ulong,ulong>::Add 294 1
7.14%
0
0.00%
   this.Tickets[this.Amount - 1] = (long)TicketDeal; 626 1
7.14%
0
0.00%
void OnStart() 3 13
92.86%
0
0.00%
MT4HISTORY::RefreshHistory 588 6
42.86%
0
0.00%
   _B2(this.RefreshHistory()); 763 6
42.86%
0
0.00%
 
fxsaber #:

Прошу помощи в расшифровке результатов профилировщика.

Что не понятно?

Я обычно сортирую по Total CPU, и смотрю, что больше всего тормозит программу в целом. Бывает полезно.

У себя с 5700 ордерами в истории при первом запуске получил почти пустой отчет, а потом вот такое:

Больше всего съедают HistoryDealGetInteger (все вызовы заняли 36%) и HistorySelect (27%). Потом идет HistoryOrderGetInteger (18%) и глобал_инициализация (9%).

Оставшиеся 10% ушли на остальной код.


Но на таком быстром одиночном выполнении на результаты смотреть смысла нет, имхо.

 
Andrey Khatimlianskii #:

Что не понятно?

Проблема с интерпретацией. Нет понимания, что, где и как подтормаживает.

Я обычно сортирую по Total CPU, и смотрю, что больше всего тормозит программу в целом. Бывает полезно.

У себя с 5700 ордерами в истории при первом запуске получил почти пустой отчет, а потом вот такое:

Больше всего съедают HistoryDealGetInteger (все вызовы заняли 36%) и HistorySelect (27%). Потом идет HistoryOrderGetInteger (18%) и глобал_инициализация (9%).

Оставшиеся 10% ушли на остальной код.

Спасибо за развернутый ответ. Только не понял, почему 45%-строки и остальные не стали брать в расчет?

 
Andrey Khatimlianskii #:

Но на таком быстром одиночном выполнении на результаты смотреть смысла нет, имхо.

Добавил 20-ти кратное повторение на большой истории.

29.41% (непонятно от чего) приходится на закрывающую метод скобку уже после return. Сложно интерпретировать.

12345678910
Новый комментарий