Weird case: Loop runs faster with fprintf?

Hi,

I have a huge code with many functions. In that, the function that takes the most time has 4 nested loops, and I was trying to estimate the time it would take in total by printing the current counter in the loop. In doing so, I realized that the loop runs much faster when I print! I do printing via fprintf. Below is the nested loop section of the function:

if(efkFlag(3))
    for i1=1:an.movf
        rID = ID.movf(i1);
        rplace = (i1-1)*sim.dim+(1:sim.dim);
        for i2=1:an.movf
            rnnID = ID.movf(i2);
            rnnplace = (i2-1)*sim.dim+(1:sim.dim);
            for i3=1:an.fcalc
                t1 = ID.fcalc(i3);
                t2 = RN(i3);
                t3 = R(1:t2,1,i3);
                t4 = W(rID,t1);
                t5 = W(rID,t3);
                t6 = bsxfun(@minus,t4,t5');
                t7 = W(rnnID,t1);
                t8 = W(rnnID,t3);
                t9 = bsxfun(@minus,t7,t8');
                t10 = bsxfun(@times,t6,t9);

                  t11 = find(SMP(:,1)==t1,1);
                  if(~isempty(t11))
                      t10 = SMP(t11,3).*t10;
                  end  

                  for i4=1:t2
                      t12 = (i4-1)*sim.dim+(1:sim.dim);
                      t13 = KR(t12,1:sim.dim,i3);
                      t14 = t10(i4).*t13;  

                      K(rplace,rplace) = K(rplace,rplace)+t14;
                      K(rplace,rnnplace) = K(rplace,rnnplace)-t14;                   
                  end
              end
          end
          fprintf('stiffness:  %3.0f %3.0f %6.2f\n',i1,an.movf,toc/60);
      end
  end

Does anyone have an idea about why the loop would run faster?

Thanks,

[Seyhan Emre Gorucu]

Run the same case 1000 times. The first time you run it gives a large value. 1000 times takes an average. Did you do profiling or tic toc?

[Emre]

Actually, I am aware that the first time in many cases takes more time, but it is not the case here. In this one, I compare first step to first step. Or Nth step to Nth step.

Answer 1

[per isakson]

I cannot reproduce your result with the function, cssm (see below), on R2012a 64bit, Windows7. Here are two results recorded after several runs.

...
>> cssm(10);
Elapsed time is 10.712166 seconds.
...
>> cssm(10);
1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17, ...
Elapsed time is 10.700414 seconds.

.

1. The time recorded with tic/toc is hardly affected by fprintf.
2. the fprintf-output displays while looping (handled be a parallel process?)
3. profile shows "zero" time for fprintf
4. Is "Free Memory" (Windows Task Manager) close to zero anytime during the execution of your program?

    function M11 = cssm( N )
        M01 = randn( N );
        M02 = randn( N );
    tic
        for ii = 1 : 100
            for jj = 1 : 100
                for kk = 1 : 100
                    M11 = bsxfun( @times, M01, M02 );
                end
            end
    %       fprintf( '%d,', ii )
        end
    fprintf( '\n' )
    toc
    end

[Emre]

Hi per isakson. Thanks for the answer. I am trying to code a stand-alone function that shows the same weird problem. I will post it here if I can do one. My replies to your questions are: 1. It should be that way, but it definitely is not. 2. A parallel processing might be the cause, but I am not sure what parallel processing MATLAB does in the background. 3. Yes, I don't think the time elapsed while printing has an effect here. The question is why printing results with an increase in speed. 4. It is not equal to zero, and it seems like it is not that much affected by the process I run. Also, I encounter this weird case for several different problem sizes that uses very low to very big memory sources. Kind regards,

[per isakson]

Hi Embre, I assume that

1. you can reproduce my results with my function, cssm
2. you have profiled your code with and without fprintf. (The Matlab function, PROFILE.) What does it tell?

Why not send the problem to the tech support together with a clear instruction on how to run it.

Answer 2

[Sean de Wolski]

It might be even faster if you have just a drawnow where the fprintf(etc) is.

[Emre]

How could that even be possible?

[Emre]

I tried "drawnow" instead of "fprintf", and yes that even makes the code run faster! But, I still don't have an idea of why. Could you share the reason?

Answer 3

[Daniel Shub]

Are you sure it is running faster. I am not sure that fprintf actually prints to the screen in the middle of your loop. It may wait until the nested loops are finished before flushing all the answers to the screen. This would make it look like it is going fast.

[Emre]

No, I am sure it is running faster. I do both tic/toc measurements and check the time with my watch.