libsubprocess: do not spin on large lines #6281

chu11 · 2024-09-13T19:59:59Z

Problem: In several cases, libsubprocess hangs/spins can occur if the internal output buffer is full. For example, if subprocess output is line buffered and a single line exceeds the buffer size, the buffer can never be emptied because output callbacks are never called (i.e. the buffer never contains a line).

Other situations can exist if the user simply does not read data when it becomes available.

Solution: Handle full output buffers with two special cases

if output is line buffered and the buffer is full AND no line exists, call the output callback for the user to get the current data.
flux_subprocess_read_line() and similar functions will return data that is not a full line.
if the buffer is at capacity and the user elected to not read anything in the output callback, drop the data. The internal assumption is that a user must read data that is given to them at that point in time.

Fixes #6262

garlick · 2024-09-13T21:03:21Z

Nice! does this fix #4572 also?

chu11 · 2024-09-13T22:07:43Z

Hmm, I don't think so. The Value too large for defined data type suggests it might be an issue more similar to #6256

garlick

See inline comment - it seems like the second problem may be more of a documentation one?

garlick · 2024-09-23T15:21:49Z

src/common/libsubprocess/ev_fbuf_read.c

+            /* At the end of the day, there is a core assumption that
+             * users will not ignore reading data when they are told
+             * there is data to read.
+             *
+             * If the user didn't read anything above and we're out of
+             * buffer space, we gotta do something otherwise we will
+             * spin (i.e. the io watcher is currently stopped, it
+             * can't be restarted b/c the user isn't reading data,
+             * etc.)
+             *
+             * we could stop the ev watchers (prep, check, idle, and
+             * io), but this results in little ability to control
+             * "fallout" from a watcher just (effectively) exiting out
+             * of the blue.  From caller perspectives, it may have
+             * exited cleanly.
+             *
+             * we choose to dump the buffer contents instead.
+             * Unfortunately this leads to loss of data and no error
+             * message.  However in authors opinion, it is a "cleaner"
+             * fallout.
+             *
+             */


Pondering this a bit, it seems like this ev watcher ought to behave similar to the libev ev_io watcher:

http://pod.tst.eu/http://cvs.schmorp.de/libev/ev.pod#code_ev_io_code_is_this_file_descrip

That is, it should be level triggered (keep calling callback while data is available) and should be stoppable in the watcher callback. This change would drop data if the watcher chose to stop itself rather than consume the data so I think it would not be correct.

It may be good to add some inline documentation though (I guess in fbuf_watcher.h?) that the watchers are level triggered and that the read watcher must either read some data or stop the watcher to avoid unnecessary trips through the event loop without progress.

Also, maybe add documentation in subprocess.h that the output callbacks should either consume data or call flux_subprocess_stream_stop().

Maybe this PR should just ensure that, when line buffered and the buffer is full, the callback gets called even there isn't a line terminator, and level triggering documentation (and any fixes for in-tree inappropriate uses, if any) could go in a separate PR?

Maybe this PR should just ensure that, when line buffered and the buffer is full, the callback gets called even there isn't a line terminator, and level triggering documentation (and any fixes for in-tree inappropriate uses, if any) could go in a separate PR?

Let me try again to split it up. I think the reason I didn't for this PR is b/c a user not being able to read a buffer without a line == a user not reading data b/c they "forgot to". So that's why I ended up putting it all together. It led to some testing difficulties otherwise. But I'll give it another shot.

garlick · 2024-09-23T22:30:34Z

I was questioning the correctness of the proposed change for "forgot to". Edit: apologies if that was redundant!

chu11 · 2024-09-24T18:18:11Z

re-pushed, this PR is now limited to just the line buffering corner case

garlick

Looking good! I have a few comments that are mostly trivial.

I did want to manually kick it a bit with lptest and see how things go so I'll save approval for after that test.

garlick · 2024-09-24T17:47:53Z

src/common/libsubprocess/test/iostress.c

+    // libsubprocess will attempt to get the user to read from the buffer that
+    // is overrun.  So generally speaking, stdout buffer overrun should still
+    // work.
+    ok (iostress_run_check (h, "tinystdout", false, 0, 128, 1, 1, 256),
+        "tinystdout works");


"buffer overrun" kind of implies that data is lost (to me).

Maybe the comment should just be

// When the line size is greater than the buffer size, all the data is transferred. // flux_subprocess_read_line() will receive a "line" that is not terminated with \n

garlick · 2024-09-24T17:54:53Z

src/common/libsubprocess/subprocess.h

+ *
+ *   This function may return an incomplete line under the rare
+ *   circumstance the stream has closed and last output is not a line.


Suggestion: s/under the rare circumstance/when/

This is a general purpose library so the fact that it's rare for job stdout doesn't necessarily mean API users should consider it rare.

garlick · 2024-09-24T17:56:23Z

src/common/libsubprocess/remote.c

    /* no need to handle failure states, on fatal error, these
     * reactors are closed */


Not related to this PR but happened to notice this comment is cut & pasted in two places.

Suggestion: s/reactors/watchers/ and perhaps name the watchers that are supposed to be stopped?

garlick · 2024-09-24T18:12:59Z

src/common/libsubprocess/remote.c

+        /* In the event the buffer is full, the `fbuf_write()` will
+         * fail.  Call user callback to give them a chance to empty
+         * buffer.  If they don't, we'll hit error below.
+         */
+        if (!fbuf_space (c->read_buffer))
+            c->output_cb (c->p, c->name);
+


Was going to comment that throwing an error here is not consistent with allowing the user to stop the stream from the callback, but I see the stream_start/stop functions are noted to be for local processes only.

We can fix that once we have credit based flow control since the remote will never send more data than we have room to put in the buffer.

the callback placement here is unfortunate, the reason was the libev did not call things in the order I expected. I expected:

output - put data in buffer, start output prep/check check_cb - call output callback since there's data in the buffer <start next iteration of libev loop>

but what happened was

output - put data in buffer, start output prep/check <start next iteration of libev loop> prep_check - see data in output buffer, start idle output - want to put more data in buffer, hit EOVERFLOW check_cb - this is never reached because of error above

the fact I just started the prep/check means check isn't called in the current iteration.

We can fix that once we have credit based flow control since the remote will never send more data than we have room to put in the buffer.

The work on #6291 is only for stdin since that's the specific case brought up by the user. But yeah, for output we should add that as a todo as well.

On the order of events, should the output watcher be stopped when the buffer is full then, and restarted when it's not?

i was thinking about that after writing the above. The output data is coming from the rexec_continuation(), which is just the stream of responses from the server. So I don't think we can stop it.

BUT ... then I thought, could we requeue the message at the head of the queue if space is full? Thus the future would be re-called the next iteration in the same way? That would allow us to also alter the behavior to behave more like the io reactor (i.e. spin instead of error out). I don't know how safe or unsafe this is. Skimming code, I guess flux_future_get() can return a message as a string, then we gotta make it a flux message, and put it back in via flux_requeue()?

Another route might be to expose watcher priorities in our APIs, and then use them to ensure this check watcher runs before anything else.

I wasn't aware of the libev priority stuff. Hmmmm. I suppose that could be an option, but at this point in time I'm not sure we have a way to add a priority to whatever underneath the covers is calling the flux future's then callback? So perhaps this is something to simply kick the can down the road.

Well we could elevate the priority of just this check watcher to get it to be called before the check watcher in the future implementation. Did you want to pause and try that? I could give you a commit that adds a flux_watcher_set_priority() function to cherry pick. Just as an experiment?

Untested but here it is: 1932ce5

Just call flux_watcher_set_priority (check_watcher, 1);

That should raise the priority from the default of 0 to 1. if that doesn't work try 2 :-) 2 is the max.

Edit: it has to be called before the watcher is started.

Did you want to pause and try that?

As this would involve more than a few line tweak, I'm inclined to merge this PR and experiment with it in a different PR. But lets log so we don't forget this conversation.

Edit: see #6302

garlick · 2024-09-24T18:18:30Z

src/common/libsubprocess/test/stdio.c

+    diag ("overflow_output_buffer");
+    test_overflow_output_buffer (r);


Suggestoin: rename this test to something like test_long_lines() or similar since the point is to demonstrate that the buffer does not overflow when it gets a long line.

garlick

I did some testing with flux exec running lptest with various line sizes and lengths, and comparing the output to the same command run locally. I even tried 4G worth of (4MB-500B) lines! No issues.

I then repeated some of these tests with the data going to a job's stdout. Also no issues.

Approving! Nice work.

chu11 · 2024-09-24T21:05:18Z

re-pushed with tweaks per comments above

Problem: Some comments are a bit unclear because the word "reactor" was used in place of "watcher". Update comments.

Problem: It'd be nice to know how many times the output callback is called, but that is not tracked. Add an output count to the output cb and output its result in diagnostics.

Problem: The flux_subprocess_read_line() function may return an incomplete line if the last output of the stream is not a line. This is not documented. Document this in subprocess.h.

Problem: libsubprocess can hang/spin if the output buffer is line buffered and a line exceeds the current output buffer size. The buffer can never be emptied because output callbacks are never called (i.e. the buffer never contains a line). Solution: If output is line buffered and the buffer is full AND no line exists, call the output callback for the user to get the current data. flux_subprocess_read_line() and similar functions will return data that is not a full line. Fixes flux-framework#6262

Problem: There are no unit tests for when a single line exceeds the size of an output buffer. Add unit tests.

codecov · 2024-12-24T17:30:35Z

Codecov Report

Attention: Patch coverage is 90.90909% with 1 line in your changes missing coverage. Please review.

Project coverage is 83.31%. Comparing base (67d7f80) to head (3302805).
Report is 554 commits behind head on master.

Files with missing lines	Patch %	Lines
src/common/libsubprocess/fbuf_watcher.c	50.00%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #6281      +/-   ##
==========================================
- Coverage   83.32%   83.31%   -0.02%     
==========================================
  Files         523      523              
  Lines       86124    86133       +9     
==========================================
- Hits        71766    71759       -7     
- Misses      14358    14374      +16

Files with missing lines	Coverage Δ
src/common/libsubprocess/ev_fbuf_read.c	`92.85% <100.00%> (+0.08%)`	⬆️
src/common/libsubprocess/remote.c	`78.43% <100.00%> (+0.34%)`	⬆️
src/common/libsubprocess/subprocess.c	`88.86% <100.00%> (+0.03%)`	⬆️
src/common/libsubprocess/fbuf_watcher.c	`83.62% <50.00%> (-0.59%)`	⬇️

... and 6 files with indirect coverage changes

chu11 force-pushed the issue6262_libsubprocess_lines branch 2 times, most recently from cc9b4fe to 898611b Compare September 13, 2024 22:39

garlick reviewed Sep 23, 2024

View reviewed changes

chu11 force-pushed the issue6262_libsubprocess_lines branch from 898611b to 93b87e0 Compare September 24, 2024 17:36

chu11 changed the title ~~libsubprocess: do not spin on full output buffer~~ libsubprocess: do not spin on large lines Sep 24, 2024

chu11 force-pushed the issue6262_libsubprocess_lines branch from 93b87e0 to 3b6bd81 Compare September 24, 2024 17:57

garlick reviewed Sep 24, 2024

View reviewed changes

garlick approved these changes Sep 24, 2024

View reviewed changes

chu11 mentioned this pull request Sep 24, 2024

libsubprocess: support stdout flow control #6300

Open

chu11 force-pushed the issue6262_libsubprocess_lines branch from 3b6bd81 to f3652f9 Compare September 24, 2024 21:05

chu11 mentioned this pull request Sep 24, 2024

libsubprocess: increase priority of output check watcher #6302

Closed

chu11 force-pushed the issue6262_libsubprocess_lines branch from f3652f9 to 41d9426 Compare September 24, 2024 23:27

chu11 added the merge-when-passing label Sep 24, 2024

chu11 force-pushed the issue6262_libsubprocess_lines branch 3 times, most recently from 5fa082d to 26ed51c Compare September 25, 2024 16:59

chu11 added 5 commits September 25, 2024 10:00

libsubprocess: clarify some comments

2961d11

Problem: Some comments are a bit unclear because the word "reactor" was used in place of "watcher". Update comments.

libsubprocess/test: add output count

23c21d5

Problem: It'd be nice to know how many times the output callback is called, but that is not tracked. Add an output count to the output cb and output its result in diagnostics.

libsubprocess: document corner case

2063039

Problem: The flux_subprocess_read_line() function may return an incomplete line if the last output of the stream is not a line. This is not documented. Document this in subprocess.h.

libsubprocess/test: cover line buffer overflow

3302805

Problem: There are no unit tests for when a single line exceeds the size of an output buffer. Add unit tests.

chu11 force-pushed the issue6262_libsubprocess_lines branch from 26ed51c to 3302805 Compare September 25, 2024 17:00

mergify bot merged commit ab4695b into flux-framework:master Sep 25, 2024
33 checks passed

chu11 deleted the issue6262_libsubprocess_lines branch September 25, 2024 18:19

chu11 mentioned this pull request Sep 25, 2024

libsubprocess: add extra documentation #6307

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

libsubprocess: do not spin on large lines #6281

libsubprocess: do not spin on large lines #6281

chu11 commented Sep 13, 2024

garlick commented Sep 13, 2024

chu11 commented Sep 13, 2024

garlick left a comment

garlick Sep 23, 2024

garlick Sep 23, 2024 •

edited

Loading

chu11 Sep 23, 2024

garlick commented Sep 23, 2024 via email •

edited

Loading

chu11 commented Sep 24, 2024

garlick left a comment

garlick Sep 24, 2024

garlick Sep 24, 2024

garlick Sep 24, 2024

garlick Sep 24, 2024

chu11 Sep 24, 2024

chu11 Sep 24, 2024

garlick Sep 24, 2024

chu11 Sep 24, 2024 •

edited

Loading

chu11 Sep 24, 2024

garlick Sep 24, 2024

garlick Sep 24, 2024 •

edited

Loading

chu11 Sep 24, 2024 •

edited

Loading

garlick Sep 24, 2024

garlick Sep 24, 2024

garlick left a comment

chu11 commented Sep 24, 2024

codecov bot commented Dec 24, 2024

		/* no need to handle failure states, on fatal error, these
		* reactors are closed */

		diag ("overflow_output_buffer");
		test_overflow_output_buffer (r);

libsubprocess: do not spin on large lines #6281

libsubprocess: do not spin on large lines #6281

Conversation

chu11 commented Sep 13, 2024

garlick commented Sep 13, 2024

chu11 commented Sep 13, 2024

garlick left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

garlick Sep 23, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

garlick commented Sep 23, 2024 via email • edited Loading

chu11 commented Sep 24, 2024

garlick left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chu11 Sep 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

garlick Sep 24, 2024 • edited Loading

Choose a reason for hiding this comment

chu11 Sep 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

garlick left a comment

Choose a reason for hiding this comment

chu11 commented Sep 24, 2024

codecov bot commented Dec 24, 2024

Codecov Report

garlick Sep 23, 2024 •

edited

Loading

garlick commented Sep 23, 2024 via email •

edited

Loading

chu11 Sep 24, 2024 •

edited

Loading

garlick Sep 24, 2024 •

edited

Loading

chu11 Sep 24, 2024 •

edited

Loading