Basic C / C++ explanation

Question

I wanted to check the performances of an algorithm in computer vision and I ended up with this basic piece of code just to check what loop was the fastest. But I do not have any explanation on the result. I generally get a result showing that the double for loop is 3 times faster that the simple loop. And if I switch the two loops, I get the same result, which means that the second one is always optimized ... So what kind of optimization does the compiler make ?

I am sorry I know this must be a silly question ...

ulong k = 0;
auto start = std::chrono::high_resolution_clock::now();
for( uint i = 0; i < 1000000; ++i )
{
    k++;
}
auto diff = std::chrono::high_resolution_clock::now() - start;
auto t1 = std::chrono::duration_cast<std::chrono::nanoseconds>(diff);

k = 0;
start = std::chrono::high_resolution_clock::now();
for( uint i = 0; i < 1000; ++i )
{
    for( uint j = 0; j < 1000; ++j )
    {
        k++;
    }
}
diff = std::chrono::high_resolution_clock::now() - start;
auto t2 = std::chrono::duration_cast<std::chrono::nanoseconds>(diff);

CL_PRINT( "Simple: ", t1.count() );
CL_PRINT( "Double: ", t2.count() );

And if I switched the two loops, I get the same result, which means that the second one is always optimized ...

Note that CL_PRINT is just a macro for debug purposes. Also note that I compile the code with those options: -O3 -msse4.1

Answer 1

The answer here is that the exact timing varies. When I run this code on my machine, it comes up with 1000 for the first loop sometimes, and 1000 for the second loop at other times. It's just "luck" when the timer ticks over. If you have a more accurate timer, it may show differences based on how long it takes to read the timer, or some such.

$ ./a.out
k = 1000000
k = 1000000
Simple: 0
Double: 1000
$ ./a.out
k = 1000000
k = 1000000
Simple: 1000
Double: 0
$ ./a.out
k = 1000000
k = 1000000
Simple: 1000
Double: 0
$ ./a.out
k = 1000000
k = 1000000
Simple: 1000
Double: 0

It is easy to see that BOTH loops are optimized out:

main:
.LFB1474:
.cfi_startproc
pushq   %rbp
.cfi_def_cfa_offset 16
.cfi_offset 6, -16
pushq   %rbx
.cfi_def_cfa_offset 24
.cfi_offset 3, -24
subq    $8, %rsp
.cfi_def_cfa_offset 32
call    _ZNSt6chrono12system_clock3nowEv
movq    %rax, %rbx
call    _ZNSt6chrono12system_clock3nowEv
movl    $.LC0, %esi
**subq  %rbx, %rax**
movl    $_ZSt4cout, %edi
imulq   $1000, %rax, %rbp
call    _ZStlsISt11char_traitsIcEERSt13basic_ostreamIcT_ES5_PKc
**movl  $1000000, %esi**
movq    %rax, %rdi
call    _ZNSo9_M_insertImEERSoT_
movq    %rax, %rdi
call    _ZSt4endlIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_
call    _ZNSt6chrono12system_clock3nowEv
movq    %rax, %rbx
call    _ZNSt6chrono12system_clock3nowEv
movl    $.LC0, %esi
**subq  %rbx, %rax**
movl    $_ZSt4cout, %edi
imulq   $1000, %rax, %rbx
call    _ZStlsISt11char_traitsIcEERSt13basic_ostreamIcT_ES5_PKc
**movl  $1000000, %esi**
movq    %rax, %rdi
call    _ZNSo9_M_insertImEERSoT_
movq    %rax, %rdi
call    _ZSt4endlIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_
movl    $.LC1, %esi
movl    $_ZSt4cout, %edi
call    _ZStlsISt11char_traitsIcEERSt13basic_ostreamIcT_ES5_PKc
movq    %rbp, %rsi
movq    %rax, %rdi
call    _ZNSo9_M_insertIlEERSoT_
movq    %rax, %rdi
call    _ZSt4endlIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_
movl    $.LC2, %esi
movl    $_ZSt4cout, %edi
call    _ZStlsISt11char_traitsIcEERSt13basic_ostreamIcT_ES5_PKc
movq    %rbx, %rsi
movq    %rax, %rdi
call    _ZNSo9_M_insertIlEERSoT_
movq    %rax, %rdi
call    _ZSt4endlIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_
addq    $8, %rsp
.cfi_def_cfa_offset 24
xorl    %eax, %eax
popq    %rbx
.cfi_def_cfa_offset 16
popq    %rbp
.cfi_def_cfa_offset 8
ret

You can clearly see the constants for K being inserted into the stream as constants, and the time for "before" and "after" is taken and then subtracted without (much) code in between. (The "interesting" bits are marked with ** ... ** - it doesn't make it bold in code of course)