   Profiling Release Build with own Profiler (c++)
  Hi.With performace counters, one could easily get cpu ticks for a particular time step. For example, I use the rdtsc register/call to grap the cpu ticks.This functionality, I build into my own RAII style code profiler. It works somthing like this:{ PROFILE("Some name", "Some Desc", a_profiler ) ;}Where PROFILE is a macro which starts a profile section. In the ctor of this object, the rdtsc counter is started. And at the end of the section, i.e. at },the dtor is called, which ends the rdtsc counter.Now, the problem is, in debug mode, everythig works just fine, but with enabled optimization of the compiler, then nothing works anymore.Example:{ // cpp vec3_t v1(1.0f,2.0f,3.0f) ; vec3_t v2(v1), v3(v1) ; { // start profiling  PROFILE( "Profile add(+=)","Profiles the cpp add operation",MY_PROF ) ;  for( int i=0; i<NUM_ADDS; ++i )   v1 += v2 ; } // end profiling}This piece of code should profile NUM_ADDS additions of my vector addition.In debug mode, no problem. But in release mode with optimization, the compiler mixes the asm code. I show you:{ // cppvec3_t v1(1.0f,2.0f,3.0f) ;vec3_t v2(v1), v3(v1) ;{PROFILE( "Profile add(+=)","Profiles the cpp add operation",MY_PROF ) ;00DC3A32 F6 05 AC 7B DD 00 04 test   byte ptr [$S1 (0DD7BACh)],4 00DC3A39 0F 85 FF 00 00 00 jne    00DC3B3E 00DC3A3F 83 0D AC 7B DD 00 04 ordword ptr [$S1 (0DD7BACh)],4 //// .. more asm here [1]////// now the profiler starts profiling. It calls the begin function where// the counter is started.//00DC3B43 E8 55 D8 FF FF   call   nsVerzerrtProfile::profile_node::Begin (0DC139Dh) for( int i=0; i<NUM_ADDS; ++ i ){ v1 += v2 ;}}00DC3B48 B9 10 79 DD 00   mov    ecx,offset _pn (0DD7910h)//// here the profile node just ends prfiling by ending the counter...// so just 3 lines of asm code is profiled, instead of the complete for loop.//00DC3B4D E8 20 D6 FF FF   call   nsVerzerrtProfile::profile_node::End (0DC1172h) As you can see in the msvc asm code, the profiled section is moved BEHIND the for loop code at[1] which I want to profile. At [1] the for loop is exected.Its even worse, if I just use the function, which gets the ticks from the rdtsc reg, directly, the same situation appears. It is, the code of the for loop is moved in front of the rdtsc call.But this all means, using this kind of profiling in release code is useless.So, using any kind of counters in code is useless, becase the compiler is putting it elsewhere, or at least, the profiled code is put elsewhere by the compiler(in my case).What can I do to avoid this kind of situation? Is it possible to instruct the compiler to put the counter->begin and counter->end functions at a specific place, i.e, where it is placed in the code, and not where the compiler wants it to be?ThanksAlex   
  Your RAII class contains timer values. Mark that variable volatile.struct Timer {  volatile long start_time;  volatile long end_time;};This hints the compiler that it should not rearange the code that accesses it.The actual variable that you use here depends on API. So it will be either time_t or LARGE_INTEGER. As consequence, the operation that writes into it will be affected by volatile as well.There are however no guarantees about portability or reliability of this approach.RDTSC is also not best choice for this, unless you guarantee that you will be manually enforcing affinity of threads. Use QPC or equivalent solution. With RDTSC, anything lasting longer than a context switch is too likely to give incorrect reading, it's only suitable for very short tests in controlled environment.Also, are you serializing the call to RDTSC with CPUID?   ;  Hi Antheus.Thanks for that fast reply.Before I try the volatile "trick", I want to say that I tried it at the object which is created by the macro PROFILE. But this hasn't worked. It looked like this.#define PROFILE( name, description, profiler ) static nsVerzerrtProfile::profile_node _pn(name, description, profiler, __FUNCTION__, __LINE__, __FILE__) ; volatile nsVerzerrtProfile::profile_section _ps( &_pn ) ; // RAII stype profile section where I tried the volatile, but it doesnt worked that way...( there should be some \ at the end of the lines...)I thought this is enough to tell the compiler to leave it in the code where I put it in. I will put the volatile directly to the variables and see what happens...Quote:Also, are you serializing the call to RDTSC with CPUID?What do you mean by this?Currently, I just fire an rdtsc, but doing no CPUID stuff.Before that, I used the win perf counter, but read, that this counter is to heavy, so I tured to the rdtsc call.Alex   ;  Unfortunately, it doesnt work.I made every atomic variable volatile. But it failed.The call to the begin function just appears where it was before the volatile declarations.What could I do now?I would like to profile the optimized code.Thanks   ;  Out of curiosity, which compiler are you using?One possible workaround is to try putting the profiling code and the loop into separate functions, something like this:void profile(void){ PROFILE( "Profile add(+=)","Profiles the cpp add operation",MY_PROF ) ; test();}// Might need to put this in a separate .cpp file to prevent function inliningvoid test(void){ vec3_t v1(1.0f,2.0f,3.0f) ; vec3_t v2(v1), v3(v1) ; for( int i=0; i<NUM_ADDS; ++i )   v1 += v2 ;}I believe that will persuade the compiler to do things in the right order.As long as NUM_ADDS is suitably large, the overhead of the function call won't affect the results significantly. However, you may also want to make test() actually compute something - a good optimizer could turn the whole function into a single ret instruction, as long as it can inline that operator+=().   ;  Hi Adam_42.I also tried your solution of putting the code into a separate function before.But this results in exactly the same situation. I.e. the compiler put the beginning and the end of the profiling behind the code which is to profile.I use msvc++ of visual studio professional(academic version(mybe this is of any relevance)).I compile with optimization flag /Ox and debug information /Zi. This allows my to put breakpoints in visual studio, so i can observe the asm code the msvc has generated.I just want to add the fact, that my profiler is a bit more complex. So it is not in terms of simply call timer->getticks...I dont want to burden you with that complexity. If we come to a solution without posting the code, it would be great...And I want to add the fact, that I was inspired by some game programming gems(gpg) articles, and there the authors even dont mention any release build issue. So this leads me to the fact, that even the various gpg profilers dont work for release builds or, they simply dont revealed the complete code...Alex   ;  After looking at assembly, the problem isn't in profiling.It's in the fact that compiler is capable of calculating the result of your loop during compilation, and it merely inserts the results.This is the problem with this type of profiling.Do something like this:struct Test {  virtual void run() = 0;};struct NopTest : public Test {  virtual void run() {   }};struct AdditionTest : public Test {  ~AdditionTest() {    std::cout << v1;  }  virtual void run() {v1+=v2;  }  vec3_t v1, v2, v3;};To profile, then do something like:Test * ptr = new AdditionTest();Test * nop = new NopTest();//profile the time ofptr->run();// and subtract the profiling results ofnop->run();But as far as real-world test goes - the profiler is correct. Your operation takes no time, since there is nothing to do.   ;  Hi Antheus.Sorry to tell you, but this also results in the same behaviour as before.Now the compiler just returns within the virtual function and no code is performed there.Here is the cpp code:{ PROFILE( "Profile cross prod","Profiles the cpp cross prod operation",MY_PROF ) ; cross_test_cpp_1->run() ;}here the disassembly//// ... asm code here. This is the for loop ...//013F2F1F B9 28 75 40 01   mov    ecx,offset _pn (1407528h) 013F2F24 C7 44 24 14 28 75 40 01 mov    dword ptr [esp+14h],offset _pn (1407528h) //// Start profiling//013F2F2C E8 7B E4 FF FF   call   nsVerzerrtProfile::profile_node::Begin (13F13ACh) //// [1]//cross_test_cpp_1->run() ;013F2F31 8B 0D 0C 7D 40 01 mov    ecx,dword ptr [cross_test_cpp_1 (1407D0Ch)] 013F2F37 8B 11  mov    edx,dword ptr [ecx] 013F2F39 8B 02  mov    eax,dword ptr [edx] 013F2F3B C7 84 24 C0 07 00 00 2D 00 00 00 mov    dword ptr [esp+7C0h],2Dh //// calls the virtual function as stated at [1] but following this // call just results in a single ret operation.// [2]//013F2F46 FF D0  call   eax  }013F2F48 B9 28 75 40 01   mov    ecx,offset _pn (1407528h) 013F2F4D 89 9C 24 C0 07 00 00 mov    dword ptr [esp+7C0h],ebx //// end profiling//013F2F54 E8 28 E2 FF FF   call   nsVerzerrtProfile::profile_node::End (13F1181h) //// ...//As you can see, here just some more asm operations are profiled, but not thefor loop.Here is the call to the virtual function, see[2] in previouse disassembly://*************************************************************************struct cross_test_cpp : public test{virtual void run( void ){vec3_t x(1.0f,0.0f,0.0f) ;vec3_t y(0.0f,1.0f,0.0f) ;vec3_t z(0.0f,0.0f,1.0f) ;vec3_t out ;for( int i=0; i<NUM_CROSS; ++ i )out = x.cross(y) ;}013F4C60 C3ret    As you can see, just one single ret..This code...{PROFILE( "Profile scalar(*=)","Profiles the sse3 mult operation",MY_PROF ) ; for( int i=0; i<NUM_ADDS; ++ i )  v3 *= 5.0f ;}... is very simple and quick and dirty for fast code checks. So its very bad that this doesnt work. Alternitively using more complex solutions for this kind of profiling is to omit, in my opinion, because I dont want to create a separate file for every single and simple test case... You know I mean!?Full blown classes for this kind of simple code snipets I like to profile is just overkill.One thing I want to mention. The profiler seems just to optimize the for loop.Even in the virtual function. But the code from my profiler is just at the place where it is supposed to, i.e. in the profiling function and not mix anywhere else...Maybe the for loop is too simple, so the compiler just optimizes itAlex   ;Quote:Original post by directNoobHere is the call to the virtual function, see[2] in previouse disassembly:Yes, this is why I deliberately made vectors class members, and emit v1 to std::cout. Otherwise the run() function has no side-effects, and is optimized out by the compiler.This is *correct behavior* of optimizing C++ compiler, which is free to omit dead code.The profiler, assembly and compiler are all correct, and produce desired result.Quote:So its very bad that this doesnt work.The main problem here is that you are asking your profiler the wrong question. You want to know how long unoptimized statement runs, but compiler is answering with optimized case - which is a nop.The question you want to ask is about the cost of side-effect, not the cost of operation. You don't care *how* this is done (optimizing compiler takes care of that), you want to know the cost of change (vector addition). This means among other things to actually need the variables in first place.Usual way to do this is to print out all the variables (regardless of their value) after the profiling test. Another issue to avoid is not to use hard-coded values, but accept them from argv and argc, to prevent compiler from knowing the values, but this still results in too optimized case due to somewhat fixed addresses and potential loop optimizations.   ;  Ok, something changed, but still, I just get wrong results.All in all, I cant assign concrete asm operations to the function I like to profile, because in the virtual run function are various other operations now.For example, I implemented a cpp and a sse version of the cross product.But in the for loop of the cpp cross product test are much less asm operations than in the for loop testing the sse implementation...This is cracy. How can I be sure, that the compiler gives me what I want to see???Quote:The main problem here is that you are asking your profiler the wrong question. You want to know how long unoptimized statement runs, but compiler is answering with optimized case - which is a nop.Yea, why than bother with profiling the optimized code, when the compiler is just doing what the compiler does!? I mean, its nice from the compiler optimizing my code, but in this case, I hate him!Currently Im just thinking, its useless to profile release code with the kind of profilers mentioned above because you cant be sure if the compiler put the right function in the right place.Alex   