About the MT5 code profiler - page 5

New comment
 
The only thing confusing is the second slip. The rest is all in place.

Let's find out
 
Renat Fatkhullin #:
The only embarrassment is the second slip. The rest is fine.

Apparently, the profiler is not suitable for the purpose of speeding up chunks of code that run faster than a few milliseconds.

  
#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);
}

The EA is in a slip for 30ms and the profiler shows that it was in a function with three additions and two multiplications for as much as 13%!


And this is what b2593 shows.

There's zero there! Because, indeed, there is zero there. Moreover, on the second report, everything is abundantly clear.


Let's sort it out so we can improve, not swear.

 
fxsaber #:

The profiler shows that as much as 13% of it was in a function with three additions and two multiplications!

That's why I wondered why the EA whose full OnTick pass takes on average 3 ms (it's full of calculations and working with trading environment) when profiling supposedly 60% is in "three additions and two multiplications". Came up with these succinct examples.


I want to use an old profiler in MT5, but I have to make such dances with builds. I have not managed to run it yet.

 
fxsaber #:

Please help me interpret the profiler data with a simple example.


It all looks like a lot of nonsense.

  • Sleep(2) is completely missing.
  • For some reason USAGE is eating up several times more than Sleep(1).


Really trying to get the hang of it, no luck yet.


Also tried Sleep replacement.

Still not clear profiler values.

What's in call report?

I have an impression that this code doesn't correspond to screenshot report.
Are you sure you didn't fix the code while the profiler was working?

 
Ilyas #:

What's in the call report?

The impression is that the code given does not match the report in the screenshot.
You sure you didn't fix the code while the profiler was running?

No, I didn't.


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)
 

I need help in deciphering the profiler results.

#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 constool 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 #:

Please help me to decipher the results of the profiler.

What is not clear?

I usually sort by Total CPU, and see what slows down the program the most overall. It can be useful.

I have a 5700 orders in my history, and the first time I run it, I get almost a blank report, and then I get something like this:

HistoryDealGetInteger (all calls took 36%) and HistorySelect (27%) eat the most. Then comes HistoryOrderGetInteger (18%) and global_initialization (9%).

The remaining 10% was spent on the rest of the code.


But there's no sense in looking at the results during such a fast single execution, imho.

 
Andrey Khatimlianskii #:

What is not clear?

A problem with interpretation. No understanding of what, where and how is slowing down.

I usually sort by Total CPU, and see what's slowing down the program the most overall. It can be useful.

I've got almost blank report on first run with 5700 orders in history, and then I've got this:

HistoryDealGetInteger (all calls took 36%) and HistorySelect (27%) eat the most. Then comes HistoryOrderGetInteger (18%) and global_initialization (9%).

The remaining 10% went to the rest of the code.

Thank you for your detailed answer. I just don't understand why the 45%-strings and the rest were not taken into account?

 
Andrey Khatimlianskii #:

But there's no point in looking at the results on such a quick single, imho.

I added a 20x repetition on a long history.

29.41% (it's unclear why) is due to a closing parenthesis after return. It's difficult to interpret.

1234567
New comment
Reason: