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

Новый комментарий
 
lynxntech #:

просто никто не понял в чем его задача сейчас,

все же просто там, невидимый таймер делает стоп и куда он чаще попадает надо смотреть что там, легкая строка или тяжелая функция

отличие от старого функционала, что этот нужно подольше подержать в запуске

add

если функция тяжелая и часто вызывается, в нее и будет постоянно ударять таймер, смотрим значит что можно с ней сделать

Идеальный результат - что то типа проверка рабочего времени, у меня там профайлер постоянно показывает остановки

Повысим в несколько раз частоту замеров и посмотрим на результат.

Это проблема всех профайлеров оптимизированного кода. Любая попытка инструментации кода в разы изменяет результаты и показывает на совершенно не на те узкие места.

И еще важно знать, что быстрые однопроходные места практически попадают в слепую зону и в отчетах видны главным образом цикличные куски кода.
 
Renat Fatkhullin #:

Повысим в несколько раз частоту замеров и посмотрим на результат.

Это проблема всех профайлеров оптимизированного кода. Любая попытка инструментации кода в разы изменяет результаты и показывает на совершенно не на те узкие места.

И еще важно знать, что быстрые однопроходные места практически попадают в слепую зону и в отчетах видны главным образом цикличные куски кода.

Поэтому люди пытаются образцы этх быстрых мест (которые выполняются может и быстро, но на каждом тике, стакане, таймере, транзакции, ...) ставить в циклы, чтобы понять, какой из вариантов реализации лучше использовать. А компилятор эти тестовые, но фактически пустые (т.е. "бесполезные"), циклы выпиливает.

 
lynxntech #:

если функция тяжелая и часто вызывается, в нее и будет постоянно ударять таймер, смотрим значит что можно с ней сделать

Форум по трейдингу, автоматическим торговым системам и тестированию торговых стратегий

О профилировщике кода MT5

fxsaber, 2023.10.28 20:58

десятки процентов TotalCPU приходится на одну из функций, которая не должна вызываться.

Ну мало ли я ошибся? Ставлю туда BreakPoint и запускаю Debug в тестере. Не срабатывает!

 
fxsaber #:

с виду простая схема, просто считать сколько куда упал взор,

надо просить Рената, напомнить, что он смотрел два варианта профайлера

 
Главное не в том, что разные принципы работы старого профайлера и нового. А в том, что один из них великолепно справляется с задачей нахождения слабых мест, другой - отвратительно.
 
fxsaber #:
Главное не в том, что разные принципы работы старого профайлера и нового. А в том, что один из них великолепно справляется с задачей нахождения слабых мест, другой - отвратительно.

Ренат помню давал объяснение, на сколько это актуально сложно сказать

конкретные затупы оба способа показывают

 
Renat Fatkhullin #:

Это проблема всех профайлеров оптимизированного кода.

Может профайлить без оптимизации?

 
trader6_1 #:

Может профайлить без оптимизации?

Только в таком режиме и получается достичь хоть какого-то понимания результатов.

 
JRandomTrader #:

Поэтому люди пытаются образцы этх быстрых мест (которые выполняются может и быстро, но на каждом тике, стакане, таймере, транзакции, ...) ставить в циклы, чтобы понять, какой из вариантов реализации лучше использовать. А компилятор эти тестовые, но фактически пустые (т.е. "бесполезные"), циклы выпиливает.

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

Мы сами так делаем в реальном коде проектов в боевых условиях.

 

Выпущена бета 4050 с повышенной в 5 раз частотой семплинга(сбора статистик) профилировщика.

Обновитесь, пожалуйста. Это позволит увидеть более точную картину производительности.


Рассмотрим результаты профилировки на штатном примере MQL5\Scripts\Examples\Canvas\CanvasSample.mq5. Он хорош тем, что содержит массу мелких функций, хорошо оптимизируется и штатно завершается.

Для оценки скорости я добавил пару строк:

int OnStart(void)
  {
   ulong start_time=GetMicrosecondCount();
   ....
   Print("Elapsed: ",(GetMicrosecondCount()-start_time)/1000," ms");
   return(0);
  }



Режим полной оптимизации и инлайнинга


2023.10.29 15:46:09.027 CanvasSample (EURUSD,H1)        Elapsed: 874 ms

Результаты лучше смотреть в режиме "Functions by Lines", переключив вид в контекстном меню. Удобно экпортировать в Эксель для последующего сравнения:

Function Line Total CPU Percentage Self CPU Percentage
OnStart 19 875 100.00% 495 56.57%
      ArrayFill(m_pixels,y*m_width+x1,(x2-x1)+1,clr); 664 477 28.80% 10 2.02%
      if(ResourceCreate(m_rcname,m_pixels,m_width,m_height,0,0,0,m_format)
437 334 20.17% 0 0.00%
      x=index%m_width; 518 86 5.19% 86 17.37%
      if(x>0 && m_pixels[idx]==old_clr) 521 74 4.47% 67 13.54%
      if(x<m_width-1 && m_pixels[idx]==old_clr) 535 72 4.35% 72 14.55%
      if(idx<total && m_pixels[idx]==old_clr) 542 70 4.23% 70 14.14%
      x[i]=rand()%Width; 166 63 3.80% 0 0.00%
      if(idx>=0 && m_pixels[idx]==old_clr) 528 58 3.50% 58 11.72%
      stack[count++]=idx; 545 53 3.20% 53 10.71%
      y[i]=rand()%Height; 159 37 2.23% 0 0.00%
      x[i]=rand()%Width; 158 34 2.05% 0 0.00%
      ArrayResize(x,10); 153 34 2.05% 0 0.00%
      string text; 183 34 2.05% 0 0.00%
      x1=rand()%limit; 105 33 1.99% 0 0.00%
      y[i]=rand()%Height; 167 32 1.93% 0 0.00%
      ChartRedraw(this.m_chart_id); 438 31 1.87% 0 0.00%
      stack[count++]=idx; 531 21 1.27% 21 4.24%
      index=stack[i]; 517 11 0.66% 11 2.22%
      for(uint i=0; i<count; i++) 515 11 0.66% 10 2.02%
      for(int i=y1; i<=y3; i++) 1991 8 0.48% 1 0.20%
      idx=index+m_width; 541 8 0.48% 8 1.62%
      ArrayFill(m_pixels,y1*m_width+x1,len,clr); 1938 7 0.42% 7 1.41%
      ArrayFree(stack); 549 7 0.42% 0 0.00%
      m_fontangle=angle; 2546 6 0.36% 0 0.00%
      ArrayFill(m_pixels,i*m_width+xx1,xx2-xx1,clr); 2023 6 0.36% 6 1.21%
      stack[count++]=idx; 538 5 0.30% 5 1.01%
      if(i<0 || i>=m_height) 2005 5 0.30% 2 0.40%
      PixelSetAA(x2,y2,clr); 2235 4 0.24% 0 0.00%
      if(ArrayResize(stack,total)==-1) 511 3 0.18% 0 0.00%
      if(yy>=0 && yy<m_height) 821 3 0.18% 0 0.00%
      stack[count++]=idx; 524 3 0.18% 3 0.61%
      canvas.Update(); 124 2 0.12% 0 0.00%
      if(xx>=0 && xx<m_width) 808 2 0.12% 0 0.00%
      if(!TextSetFont(name,size,flags,angle)) 2540 2 0.12% 0 0.00%
      string m_objname; // object name 48 2 0.12% 0 0.00%
      Line(x3,y3,x1,y1,clr); 781 2 0.12% 0 0.00%
      m_pixels[idx]=clr; 523 2 0.12% 0 0.00%
      if(yy>=0 && yy<m_height) 804 1 0.06% 0 0.00%
      if(x2<0 || x1>=m_width || y<0 || y>=m_height) 656 1 0.06% 1 0.20%
      canvas.LineHorizontal(x1,x2,y1,RandomRGB()); 63 1 0.06% 0 0.00%
      while(dy>=dx) 1812 1 0.06% 0 0.00%
      LineHorizontal(x-dy,x+dy,y+dx,clr); 1815 1 0.06% 1 0.20%
      for(int i=y1; i<=y2; i++,index+=m_width) 639 1 0.06% 1 0.20%
      if(y3<0 || y1>m_height) 1976 1 0.06% 0 0.00%
      canvas.PixelSet(x1,y1,RandomRGB()); 49 1 0.06% 0 0.00%
      y2=rand()%limit; 108 1 0.06% 0 0.00%
      if(xx1>xx2) 2008 1 0.06% 1 0.20%
      ulong start_time=GetMicrosecondCount(); 21 1 0.06% 0 0.00%
      if(ObjectCreate(chart_id,name,OBJ_BITMAP_LABEL,subwin,0,0)) 331 1 0.06% 1 0.20%
      canvas.Update(); 151 1 0.06% 0 0.00%
      m_fontname =name; 2543 1 0.06% 0 0.00%
CCanvas::Line 669 2 0.23% 2 0.23%


Обратите внимание, что у программы осталось всего две функции: OnStart и CCanvas::Line, а все остальное было перемешано, оптимизировано и слито в одну большую функцию.

Достаточно понятные строки (53 шт), где были реальные затраты. Большинство линейных участков не видны по причине их оптимизированности и малым затратам.

Клики по строкам переносят внутрь заинлайненных функций - мы достаточно хорошо провели свою работу по сохранению источников инлайна при профилировке итоговой программы. Конечно, держите в уме "mix & reorder" встраиваемых строк - диффузия достаточно широка.



Режим оптимизации без инлайнинга

Время выполнения заведомо увеличилось:

2023.10.29 15:53:55.884 CanvasSample (EURUSD,H1)        Elapsed: 1106 ms    - у оптимизированной было 874 мс
Function Line Total CPU Percentage Self CPU Percentage
OnStart 19 1107 99.91% 2 0.18%
      canvas.Fill(xf,yf,RandomRGB()); 176 696 62.82% 0 0.00%
      canvas.Update(); 177 59 5.32% 0 0.00%
      canvas.Update(); 88 37 3.34% 0 0.00%
      canvas.Update(); 66 36 3.25% 0 0.00%
      canvas.Update(); 135 36 3.25% 0 0.00%
      canvas.Update(); 120 36 3.25% 0 0.00%
      canvas.Update(); 76 35 3.16% 0 0.00%
      canvas.Update(); 147 35 3.16% 0 0.00%
      canvas.Update(); 50 35 3.16% 0 0.00%
      canvas.Update(); 110 35 3.16% 0 0.00%
      canvas.Update(); 97 33 2.98% 0 0.00%
      canvas.FillCircle(x1,y1,r,RandomRGB()); 87 11 0.99% 0 0.00%
      canvas.FillTriangle(x1,y1,x2,y2,x3,y3,RandomRGB()); 134 5 0.45% 0 0.00%
      canvas.Circle(x1,y1,r,RandomRGB()); 96 4 0.36% 0 0.00%
      canvas.TextOut(x2,y2,text,clr,TA_RIGHT|TA_BOTTOM); 197 3 0.27% 0 0.00%
      canvas.FillRectangle(x1,y1,x2,y2,RandomRGB()); 109 3 0.27% 0 0.00%
      canvas.Triangle(x1,y1,x2,y2,x3,y3,RandomRGB()); 146 2 0.18% 0 0.00%
      if(!canvas.CreateBitmapLabel("SampleCanvas",0,0,Width,Height,COLOR_FORMAT_ARGB_RAW)) 34 1 0.09% 0 0.00%
      canvas.Update(); 181 1 0.09% 0 0.00%
      canvas.Update(); 54 1 0.09% 0 0.00%
      canvas.LineAA(x1,y1,x2,y2,clr,STYLE_DASHDOTDOT); 194 1 0.09% 0 0.00%
      class CCanvas 39 1 0.09% 1 50.00%
      y2=rand()%limit; 74 1 0.09% 0 0.00%
      Print("Elapsed: ",(GetMicrosecondCount()-start_time)/1000," ms"); 203 1 0.09% 1 50.00%
CCanvas::Fill 494 696 62.82% 690 62.27%
CCanvas::Update 431 379 34.21% 0 0.00%
CCanvas::LineHorizontal 645 11 0.99% 11 0.99%
CCanvas::FillCircle 1804 11 0.99% 1 0.09%
CCanvas::FillTriangle 1943 5 0.45% 5 0.45%
CCanvas::Circle 786 4 0.36% 4 0.36%
CCanvas::FillRectangle 1907 3 0.27% 3 0.27%
CCanvas::TextOut 2618 3 0.27% 0 0.00%
CCanvas::Triangle 777 2 0.18% 0 0.00%
CCanvas::Line 669 2 0.18% 2 0.18%
CCanvas::PixelSetAA 2073 1 0.09% 1 0.09%
CCanvas::LineAA 2190 1 0.09% 0 0.00%
CCanvas::CreateBitmapLabel 315 1 0.09% 0 0.00%
CCanvas::CreateBitmapLabel 323 1 0.09% 1 0.09%


Это уже никуда не годится - показываются одни вызовы функций и полный отказ от инлайнинга. При просмотре вызываемых функций достаточно хорошо показываются расходы внутри - детали в тултипах:




Отключение оптимизации и инлайнинга

По времени это катастрофа:

2023.10.29 16:03:22.267 CanvasSample (EURUSD,H1)        Elapsed: 3204 ms       - у оптимизированной было 874 мс
Function Line Total CPU Percentage Self CPU Percentage
OnStart 19 3205 100.00% 2 0.06%
      canvas.Fill(xf,yf,RandomRGB()); 176 2647 82.59% 0 0.00%
      canvas.FillCircle(x1,y1,r,RandomRGB()); 87 111 3.46% 0 0.00%
      canvas.Update(); 177 63 1.97% 0 0.00%
      canvas.Update(); 50 35 1.09% 0 0.00%
      canvas.Update(); 66 35 1.09% 0 0.00%
      canvas.Update(); 97 35 1.09% 0 0.00%
      canvas.Update(); 88 35 1.09% 0 0.00%
      canvas.Update(); 147 35 1.09% 0 0.00%
      canvas.Update(); 110 34 1.06% 0 0.00%
      canvas.Update(); 135 33 1.03% 0 0.00%
      canvas.Update(); 120 33 1.03% 1 50.00%
      canvas.Update(); 76 33 1.03% 0 0.00%
      canvas.FillRectangle(x1,y1,x2,y2,RandomRGB()); 109 31 0.97% 0 0.00%
      canvas.FillTriangle(x1,y1,x2,y2,x3,y3,RandomRGB()); 134 26 0.81% 0 0.00%
      canvas.Triangle(x1,y1,x2,y2,x3,y3,RandomRGB()); 146 6 0.19% 0 0.00%
      canvas.Line(x1,y1,x2,y2,RandomRGB()); 75 4 0.12% 0 0.00%
      canvas.Rectangle(x1,y1,x2,y2,RandomRGB()); 119 3 0.09% 0 0.00%
      canvas.Circle(x1,y1,r,RandomRGB()); 96 2 0.06% 0 0.00%
      canvas.LineVertical(x1,y1,y2,RandomRGB()); 65 1 0.03% 0 0.00%
      canvas.TextOut(x2,y2,text,clr,TA_RIGHT|TA_BOTTOM); 197 1 0.03% 0 0.00%
      if(!canvas.CreateBitmapLabel("SampleCanvas",0,0,Width,Height,COLOR_FORMAT_ARGB_RAW)) 34 1 0.03% 0 0.00%
      { 20 1 0.03% 1 50.00%
CCanvas::Fill 494 2647 82.59% 2 625 81.90%
CCanvas::Update 431 370 11.54% 0 0.00%
CCanvas::FillCircle 1804 111 3.46% 4 0.12%
CCanvas::LineHorizontal 645 110 3.43% 110 3.43%
CCanvas::FillRectangle 1907 31 0.97% 31 0.97%
CCanvas::FillTriangle 1943 26 0.81% 26 0.81%
CCanvas::Line 669 10 0.31% 10 0.31%
CCanvas::Triangle 777 6 0.19% 0 0.00%
CCanvas::Rectangle 767 3 0.09% 0 0.00%
CCanvas::Circle 786 2 0.06% 2 0.06%
CCanvas::LineVertical 619 1 0.03% 1 0.03%
CCanvas::TextOut 2618 1 0.03% 0 0.00%
CCanvas::CreateBitmapLabel 315 1 0.03% 0 0.00%
CCanvas::CreateBitmapLabel 323 1 0.03% 1 0.03%


Результат печальный и никак не помогает понять узкие места.


Вывод:

  1. Мы предлагаем три варианта профилировки с разным уровнем детализации
  2. Доказательства разного уровня оптимизации представлены
  3. Логичность профилировки именно полноценно оптимизированного кода продемонстрирована
  4. Разобраться в узких местах можно

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