tic toc delayed output inside for loop

I want to use the tic toc function to time each iteration of a for loop. Usually, this outputs the time as "Elapsed time is ... seconds." in the command window after each loop iteration. So for the following example code there would be an output approximately every 0.1 seconds on my machine.

for j = 1:20
tic
eig(rand(500));
toc
end

However, since a few days the outputs to the command window are only made after the loop finishes and I get all the 20 outputs for the 20 iterations at once in the end. I don't understand why this changed, I didn't (knowingly) change any settings and couldn't find anything, so maybe it is a bug? I updated my release version hoping that would fix it, but it didn't. I know that this behavior happens when you use tic toc inside a for loop, while a parallel pool is open, but in this case there is no parallel pool. Is there something I can do to get the old behavior where the elapsed time is printed to the command window after each iteration?

[Zinea]

This behaviour may be due to output buffering, which sometimes happens in environments that delay the display of output until a certain buffer is filled or the loop completes. You may try out the following ways to resolve the issue:

1. The 'drawnow' command can be used to force MATLAB to flush the output buffer and display the results immediately.

for j = 1:20
    tic
    eig(rand(500));
    pause(1)
    toc
    drawnow
end

2. Although you mentioned there is no parallel pool, it would be worth checking it again using:

if ~isempty(gcp('nocreate'))
    delete(gcp('nocreate'));
end

[Sam Marshalik]

I tested your (JG) script in my MATLAB (R2024a) and it ran without issues, printing the tic/toc timing with every iteration. What happens if you simplify the code and just do:

for j = 1:5
    tic
    % eig(rand(500));
    % pause(1)
    toc
    % drawnow
end
disp('Done')

Here is what I see:

Elapsed time is 0.000077 seconds.
Elapsed time is 0.000031 seconds.
Elapsed time is 0.000031 seconds.
Elapsed time is 0.000031 seconds.
Elapsed time is 0.000003 seconds.
Done

This may be a bug and is worth a call to our Techincal Support.

[Walter Roberson]

Do you happen to be doing this inside a LiveScript ?

[JG]

@Sam Marshalik thank you for the reply. If I follow your procedure, I get the same outpot to the command window, however the issue is, that it gets all printed at once, I would prefer if it prints the timea each iteration. In you last example where it has only tic toc in the loop it is hard to see, because the total time is so short.

@Jatin Singh already mentioned that this might be due to inability of tic/toc to measure these short time intervals, but the problem is the same if each loop iteration takes much longer. For example

for j = 1:5
    tic
    eig(rand(2000));
    toc
end

takes more than 2 seconds each loop, but the output is only printed after all 5 iterations. If I do

for j = 1:5
    tic
    eig(rand(200));
    pause(1);
    toc
end

each loop takes less than 2 seconds, but due to the pause, the output appears as desired.

While this is a workaround, I think there should be a better whay than to make the code pause each iteration. It also worked for me without pause in the past, that is why I am a bit puzzled about this behavior.

Also because this was asked: I am not using a Live script, but regular ".m" scripts, or paste the code directly into the command window to reproduce this.

[Jatin]

Hi @JG,

As you pointed out, the toc function should display the duration after each iteration. You might consider reporting this as a bug to MathWorks. However, I'm curious to know if obtaining the durations iteratively adds any value to your objective compared to getting all durations at once.

Answer 1

[Jatin]

Hi @JG,

The script you provided does work as intended. According to the documentation for the "tic" and "toc" functions, it is mentioned that "Sometimes programs run too fast for tic and toc to provide useful data. If your code executes in less than 1/10 of a second, consider running it in a loop and then averaging the results to find the time for a single execution."

This implies that if the code executes very quickly, it might appear as though all the output is printed simultaneously after the loop finishes. However, in reality, the output is being queued as intended by the toc function.

The below example code shows that the output to command window are not made only after the loop ends:

%toc prints the elapsed time after each loop
for j = 1:10
    tic
    pause(1)
    toc
end

Elapsed time is 1.000553 seconds.
Elapsed time is 1.000279 seconds.
Elapsed time is 1.000305 seconds.
Elapsed time is 1.000273 seconds.
Elapsed time is 1.000407 seconds.
Elapsed time is 1.000030 seconds.
Elapsed time is 1.000029 seconds.
Elapsed time is 1.000171 seconds.
Elapsed time is 1.000236 seconds.
Elapsed time is 1.000256 seconds.

As noted by @Sam Marshalik, we can observe the output after each iteration. However, what appears to be a bug might actually be due to the "tic" and "toc" functions' inability to measure precision beyond 1/10th of a second, as stated in the documentation.

Here is the documentation for "tic" and "toc" functions for more details:

https://www.mathworks.com/help/matlab/ref/tic.html

https://www.mathworks.com/help/matlab/ref/toc.html

Hope this helps!

Answer 2

[Shivam]

Hi @JG,

You can store the elapsed time in a variable and use fprintf or disp function to print the elapsed time. It will print the elapsedTime after each iteration.

Here is the workaround you can follow:

for j = 1:20
    tic;  % Start the timer
    eig(rand(500));  
    elapsedTime = toc;  % Stop the timer and get the elapsed time
    fprintf('Iteration %d: Elapsed time is %.4f seconds\n', j, elapsedTime);
end

Iteration 1: Elapsed time is 0.0921 seconds
Iteration 2: Elapsed time is 0.0845 seconds
Iteration 3: Elapsed time is 0.0907 seconds
Iteration 4: Elapsed time is 0.0865 seconds
Iteration 5: Elapsed time is 0.0994 seconds
Iteration 6: Elapsed time is 0.0905 seconds
Iteration 7: Elapsed time is 0.0889 seconds
Iteration 8: Elapsed time is 0.0852 seconds
Iteration 9: Elapsed time is 0.0939 seconds
Iteration 10: Elapsed time is 0.0884 seconds
Iteration 11: Elapsed time is 0.0909 seconds
Iteration 12: Elapsed time is 0.0848 seconds
Iteration 13: Elapsed time is 0.0880 seconds
Iteration 14: Elapsed time is 0.1003 seconds
Iteration 15: Elapsed time is 0.0889 seconds
Iteration 16: Elapsed time is 0.0861 seconds
Iteration 17: Elapsed time is 0.0904 seconds
Iteration 18: Elapsed time is 0.0843 seconds
Iteration 19: Elapsed time is 0.0883 seconds
Iteration 20: Elapsed time is 0.0885 seconds

Hope it helps.