fprintf's at beginning and end of a function called witihin parfor loop

1 view (last 30 days)
I am trying to write logging-type information to the command window from inside a function that is called within a parfor loop. Ideally, some logging info would be written at the beginning of the function and other logging info would be written at the end of the function. The problem is that both the beginning and ending logging info appear simultaneously in the command window, no matter how long the function takes. Here is a minimum working example:
parfor k=1:10
parfprintfn(k);
end
function parfprintfn(n)
wait_time = 5 + 30*rand;
fprintf('Starting parfprintfn %d with wait_time %f at %s\n',n,wait_time,datestr(now,'HH:MM:SS'));
drawnow; % has no effect
pause(wait_time);
fprintf('Finishing parfprintfn %d with wait_time %f at %s\n',n,wait_time,datestr(now,'HH:MM:SS'));
end
Below is the output from one run of the above code. Although it is not immediately obvious from this output, the problem is that--with the exception of the first four lines--the "Starting" and "Finishing" lines for a given 'n' value always appear essentially simultaneously in the command window--that is, just when the function finishes.
Starting parfprintfn 1 with wait_time 5.305391 at 08:29:26
Starting parfprintfn 2 with wait_time 28.347252 at 08:29:26
Finishing parfprintfn 1 with wait_time 5.305391 at 08:29:32
Finishing parfprintfn 2 with wait_time 28.347252 at 08:29:55
Starting parfprintfn 4 with wait_time 24.314775 at 08:29:32
Finishing parfprintfn 4 with wait_time 24.314775 at 08:29:56
Starting parfprintfn 3 with wait_time 5.957335 at 08:29:56
Finishing parfprintfn 3 with wait_time 5.957335 at 08:30:02
Starting parfprintfn 6 with wait_time 34.679176 at 08:29:55
Finishing parfprintfn 6 with wait_time 34.679176 at 08:30:29
Starting parfprintfn 7 with wait_time 34.112550 at 08:30:02
Finishing parfprintfn 7 with wait_time 34.112550 at 08:30:36
Starting parfprintfn 9 with wait_time 11.134582 at 08:30:36
Finishing parfprintfn 9 with wait_time 11.134582 at 08:30:47
Starting parfprintfn 5 with wait_time 21.041189 at 08:30:29
Finishing parfprintfn 5 with wait_time 21.041189 at 08:30:51
Starting parfprintfn 10 with wait_time 9.584767 at 08:30:47
Finishing parfprintfn 10 with wait_time 9.584767 at 08:30:57
Starting parfprintfn 8 with wait_time 16.585694 at 08:30:51
Finishing parfprintfn 8 with wait_time 16.585694 at 08:31:07
Also, by considering the wait_time values and 'now' times in this output, you can see that the 'Starting parprintfn 4' line should have been printed before the 'Finishing parprintfn 2' line (i.e., right after 'Finishing parprintfn1') if the lines were appearing in "real time".
In short, it looks like all of the fprintf output is being buffered for a function called within a parfor, and the fprintf outputs are only printed together at the end when that function finishes.
My question is, can I make the function's fprintf outputs appear in the command window temporally separated for the beginning and end of the function?
Thanks for any hints.

Accepted Answer

Walter Roberson
Walter Roberson on 26 Mar 2022
Use a parallel data queue to send messages from the workers back to the client to print.

More Answers (1)

Jeff Miller
Jeff Miller on 27 Mar 2022
Thanks Walter, that works perfectly. For anyone else interested, here's the revised version of the original code that works as expected:
q = parallel.pool.DataQueue;
afterEach(q, @disp);
parfor k=1:10
parfprintfn(q,k);
end
function parfprintfn(q,n)
wait_time = 5 + 30*rand;
s = sprintf('Starting parfprintfn %d with wait_time %f at %s',n,wait_time,datestr(now,'HH:MM:SS'));
send(q,s);
pause(wait_time);
s = sprintf('Finishing parfprintfn %d with wait_time %f at %s',n,wait_time,datestr(now,'HH:MM:SS'));
send(q,s);
end
%{
% Here is example output:
% There are long pauses between Starting & Finishing, as expected
Starting parfprintfn 2 with wait_time 28.806738 at 07:09:09
Starting parfprintfn 1 with wait_time 10.798941 at 07:09:09
Finishing parfprintfn 1 with wait_time 10.798941 at 07:09:20
Starting parfprintfn 4 with wait_time 18.599101 at 07:09:20
Finishing parfprintfn 2 with wait_time 28.806738 at 07:09:38
Starting parfprintfn 6 with wait_time 18.785156 at 07:09:38
Finishing parfprintfn 4 with wait_time 18.599101 at 07:09:39
Starting parfprintfn 3 with wait_time 26.595778 at 07:09:39
Finishing parfprintfn 6 with wait_time 18.785156 at 07:09:57
Starting parfprintfn 5 with wait_time 9.293265 at 07:09:57
Finishing parfprintfn 3 with wait_time 26.595778 at 07:10:05
Starting parfprintfn 7 with wait_time 21.593619 at 07:10:06
Finishing parfprintfn 5 with wait_time 9.293265 at 07:10:06
Starting parfprintfn 8 with wait_time 14.514761 at 07:10:06
Finishing parfprintfn 8 with wait_time 14.514761 at 07:10:21
Starting parfprintfn 10 with wait_time 22.244114 at 07:10:21
Finishing parfprintfn 7 with wait_time 21.593619 at 07:10:27
Starting parfprintfn 9 with wait_time 15.280068 at 07:10:27
Finishing parfprintfn 9 with wait_time 15.280068 at 07:10:42
Finishing parfprintfn 10 with wait_time 22.244114 at 07:10:43
%}

Products


Release

R2021a

Community Treasure Hunt

Find the treasures in MATLAB Central and discover how the community can help you!

Start Hunting!

Translated by