Libraries: MQL Plus Enhanced Debugging Support - page 4

New comment
 
fxsaber #:

I dont understand?? 

TimeIt(Func()); From __LINE__, __FILE__, __FUNCTION__ ?
...
TimeIt(Func()); From __LINE__, __FILE__, __FUNCTION__ ?

EDIT:

Oh, I understand, you want that as output, so you know from where it is coming....

The Idea was to use the "Func()" as an identifier, but I can add additional output for locating the calls...


Ill let you know when I have done that.

 
fxsaber #:


Just to be clear about this, here is the output on my terminal. - First set is without optimizations. - Second set is with optimizations, and third set is by swithcing the functions code position in the source file...




            template <typename T>
            T LIB_DBG_NAMESPACE_DEF(lib_perf, perf_R_call)(const ulong start, T retval, const ulong end, const int perf_id, const string func_id)
            {
                if(ArraySize(_call_counter) <= (int)perf_id)
                {
                    const int prev_size = ArraySize(_call_counter);
                    ArrayResize(_call_counter, perf_id + 1, 512);
                    ArrayResize(_perf_array, perf_id + 1, 512);
                    ArrayResize(_perf_min, perf_id + 1, 512);
                    ArrayResize(_perf_max, perf_id + 1, 512);
                    ArrayFill(_call_counter, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_array, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_min, prev_size, perf_id + 1 - prev_size, ULONG_MAX);
                    ArrayFill(_perf_max, prev_size, perf_id + 1 - prev_size, 0);
                }

                // Update data
                const ulong exec_micros = (start > end) ? (start - end) : (end - start);
                _call_counter[perf_id]++;
                _perf_array[perf_id]   += exec_micros;
                _perf_min[perf_id]      = (_perf_min[perf_id] > exec_micros) ? exec_micros : _perf_min[perf_id];
                _perf_max[perf_id]      = (_perf_max[perf_id] < exec_micros) ? exec_micros : _perf_max[perf_id];

                // Print user info
                LIB_DBG_NAMESPACE_DEF(lib_perf, perf_print_details)(func_id, exec_micros, _perf_array[perf_id] / _call_counter[perf_id], _perf_min[perf_id], _perf_max[perf_id], _call_counter[perf_id]);
                return(retval);
            };

            template <typename T>
            T LIB_DBG_NAMESPACE_DEF(lib_perf, perf_O_call)(const ulong start, T& retval, const ulong end, const int perf_id, const string func_id)
            {
printf("C");
ulong _start = GetMicrosecondCount();
                if(ArraySize(_call_counter) <= (int)perf_id)
                {
                    const int prev_size = ArraySize(_call_counter);
                    ArrayResize(_call_counter, perf_id + 1, 512);
                    ArrayResize(_perf_array, perf_id + 1, 512);
                    ArrayResize(_perf_min, perf_id + 1, 512);
                    ArrayResize(_perf_max, perf_id + 1, 512);
                    ArrayFill(_call_counter, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_array, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_min, prev_size, perf_id + 1 - prev_size, ULONG_MAX);
                    ArrayFill(_perf_max, prev_size, perf_id + 1 - prev_size, 0);
                }

                // Update data
                const ulong exec_micros = (start > end) ? (start - end) : (end - start);
                _call_counter[perf_id]++;
                _perf_array[perf_id]   += exec_micros;
                _perf_min[perf_id]      = (_perf_min[perf_id] > exec_micros) ? exec_micros : _perf_min[perf_id];
                _perf_max[perf_id]      = (_perf_max[perf_id] < exec_micros) ? exec_micros : _perf_max[perf_id];

                // Print user info
                LIB_DBG_NAMESPACE_DEF(lib_perf, perf_print_details)(func_id, exec_micros, _perf_array[perf_id] / _call_counter[perf_id], _perf_min[perf_id], _perf_max[perf_id], _call_counter[perf_id]);
                return(retval);
printf("C: %llu", GetMicrosecondCount() - _start);
            };

            template <typename T>
            T LIB_DBG_NAMESPACE_DEF(lib_perf, perf_R_call)(const ulong start, T& retval, const ulong end, const int perf_id, const string func_id)
            {
printf("B");
ulong _start = GetMicrosecondCount();
                if(ArraySize(_call_counter) <= (int)perf_id)
                {
                    const int prev_size = ArraySize(_call_counter);
                    ArrayResize(_call_counter, perf_id + 1, 512);
                    ArrayResize(_perf_array, perf_id + 1, 512);
                    ArrayResize(_perf_min, perf_id + 1, 512);
                    ArrayResize(_perf_max, perf_id + 1, 512);
                    ArrayFill(_call_counter, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_array, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_min, prev_size, perf_id + 1 - prev_size, ULONG_MAX);
                    ArrayFill(_perf_max, prev_size, perf_id + 1 - prev_size, 0);
                }

                // Update data
                const ulong exec_micros = (start > end) ? (start - end) : (end - start);
                _call_counter[perf_id]++;
                _perf_array[perf_id]   += exec_micros;
                _perf_min[perf_id]      = (_perf_min[perf_id] > exec_micros) ? exec_micros : _perf_min[perf_id];
                _perf_max[perf_id]      = (_perf_max[perf_id] < exec_micros) ? exec_micros : _perf_max[perf_id];

                // Print user info
                LIB_DBG_NAMESPACE_DEF(lib_perf, perf_print_details)(func_id, exec_micros, _perf_array[perf_id] / _call_counter[perf_id], _perf_min[perf_id], _perf_max[perf_id], _call_counter[perf_id]);
printf("B: %llu", GetMicrosecondCount() - _start);
                return(retval);
            };

            template <typename T>
            T* LIB_DBG_NAMESPACE_DEF(lib_perf, perf_O_call)(const ulong start, T* retval, const ulong end, const int perf_id, const string func_id)
            {
                if(ArraySize(_call_counter) <= (int)perf_id)
                {
                    const int prev_size = ArraySize(_call_counter);
                    ArrayResize(_call_counter, perf_id + 1, 512);
                    ArrayResize(_perf_array, perf_id + 1, 512);
                    ArrayResize(_perf_min, perf_id + 1, 512);
                    ArrayResize(_perf_max, perf_id + 1, 512);
                    ArrayFill(_call_counter, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_array, prev_size, perf_id + 1 - prev_size, 0);
                    ArrayFill(_perf_min, prev_size, perf_id + 1 - prev_size, ULONG_MAX);
                    ArrayFill(_perf_max, prev_size, perf_id + 1 - prev_size, 0);
                }

                // Update data
                const ulong exec_micros = (start > end) ? (start - end) : (end - start);
                _call_counter[perf_id]++;
                _perf_array[perf_id]   += exec_micros;
                _perf_min[perf_id]      = (_perf_min[perf_id] > exec_micros) ? exec_micros : _perf_min[perf_id];
                _perf_max[perf_id]      = (_perf_max[perf_id] < exec_micros) ? exec_micros : _perf_max[perf_id];

                // Print user info
                LIB_DBG_NAMESPACE_DEF(lib_perf, perf_print_details)(func_id, exec_micros, _perf_array[perf_id] / _call_counter[perf_id], _perf_min[perf_id], _perf_max[perf_id], _call_counter[perf_id]);
                return(retval);
            };



I am serious... - Thats what the compiler does. 

EDIT:

Its not an outliar, I ran it multiple times.

And here the results after stripping whitespaces and converting the file to ANSI:



 

What would be your conclusion from this:


#define LIB_PERF_PROFILING
#include <MQLplus/lib_debug.mqh> // https://www.mql5.com/en/code/32071

#define TimeIt PERF_COUNTER_TIMEIT_R
#define TimeItV PERF_COUNTER_TIMEIT_V
#define TimeItO PERF_COUNTER_TIMEIT_O

class A
{
public:
  A() { Print(__FUNCSIG__); };
  A( const A& ) { Print(__FUNCSIG__); }
};

template <typename T>
T GetT() { T Tmp; return(Tmp); }

void OnInit()
{
  Print("\nTimeItO");
  TimeItO(GetT<A>());

  Print("\nTimeItO");
  TimeItO(GetT<A>());
}




 
Dominik Christian Egert #:

What would be your conclusion from this:

That's nothing related to the compiler and is a normal behaviour at runtime. The first execution is slower then there is some cache at play. You can't expect something else on a modern computer, it depends on a lot of factors (software and hardware).

https://stackoverflow.com/questions/19388372/when-doing-performance-testing-why-are-the-initial-iterations-constantly-slower

When doing performance testing, why are the initial iterations constantly slower than the average?
When doing performance testing, why are the initial iterations constantly slower than the average?
  • 2013.10.15
  • BenR BenR 2,761 3 3 gold badges 25 25 silver badges 36 36 bronze badges
  • stackoverflow.com
It seems like every time I run performance tests, there is always a "wind down" time in the first few iterations before times stabilize. Here's the performance testing code (in this case, I was testing...
 
Dominik Christian Egert #:

I have taken a look at this phenomenon, and I am sorry to disappoint you, but there is no way this can be influenced by us.


The MQL compiler has a few very strange behaviours concerning performance, and I have had the most ridicolous findings within source code. - I reported all of these things to Alexey from Metaquotes, and I never received a satisactory answer.

It might be, by adding some comment to the lib_debug.mqh, this effect could change and move to another function. - Yes, I know, htat sounds completley like abracadabra, but thats what it is. - If you would like to investigate on that issue more, I am very willing to share the proof with you, which I have also given to metaquotes to investigate....


You will find lots of inconsistencies when regarding performance measurements. - As said, and I am sure you can see as well ,the cod eis exactly the same for both functions, still one takes significant longer than the other. - Thats due to whatever the compiler does.

If you want, Ill share the project with you, you will get an even more detailed version of that problem. - Unsolved.

As I said in my previous post, about the first measurement being slower, nothing related to the compiler. Normal behaviour.

If you have some other issues, please report it on the forum, where it can be check and reproduced, and then reported to MetaQuotes.

 
Alain Verleyen #:

That's nothing related to the compiler and is a normal behaviour at runtime. The first execution is slower then there is some cache at play. You can't expect something else on a modern computer, it depends on a lot of factors (software and hardware).

https://stackoverflow.com/questions/19388372/when-doing-performance-testing-why-are-the-initial-iterations-constantly-slower

Yes, that's what I concluded this night as well.

This case must be related to resource allocation by the OS.

Concerning the other "issue", I will share the project and findings in a new thread later today.

My suspicion about that problem is memory -paging. Because of the way the compiler "mixes" the binary code in memory. But let's investigate this...


 
Nice! Excellent work and quality code.

CPU warmup on the first run is a known problem during micro-benchmarking (due to caching and processor pipelines). If your target is to benchmark class and objects startups (worst-case running time), then only the first run is measured. 
Running the code in a loop for a number of times represents the average-case performance especially for code that will called many times during the program run.
 
Dominik Christian Egert #:

Got it...

I never use if() without brackets....

Change this line (Line Number 3351 in lib_debug.mqh

to this line:

that will fix the error...

Still some compile errors can occur:
If (condition)
  TimeItV(...);
else
   Print("failed.");

It can be avoided if macro is enclosed as #define TimeItV  do {....} while(0)
 
amrali #:
Still some compile errors can occur:
If (condition)
  TimeItV(...);
else
   Print("failed.");

It can be avoided if macro is enclosed as #define TimeItV  do {....} while(0)

Thank you for the contribution, I added your suggestion and it does solve the issue...

 
amrali #:
Still some compile errors can occur:
If (condition)
  TimeItV(...);
else
   Print("failed.");

It can be avoided if macro is enclosed as #define TimeItV  do {....} while(0)

For the record, it's very well explained "why" in the link you provided elsewhere.

https://stackoverflow.com/questions/154136/why-use-apparently-meaningless-do-while-and-if-else-statements-in-macros

Why use apparently meaningless do-while and if-else statements in macros?
Why use apparently meaningless do-while and if-else statements in macros?
  • 2008.09.30
  • jfm3 jfm3 36.6k 10 10 gold badges 32 32 silver badges 35 35 bronze badges
  • stackoverflow.com
In many C/C++ macros I'm seeing the code of the macro wrapped in what seems like a meaningless loop. Here are examples. I can't see what the is doing. Why not just write this without it?
123456789
New comment