| Message ID | 20220529105505.667891-4-zlang@kernel.org (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | random fixes for fstests | expand |
On Sun, May 29, 2022 at 06:55:03PM +0800, Zorro Lang wrote: > In generic/591.out expects below output: > concurrent reader with O_DIRECT > concurrent reader with O_DIRECT <=== ??? > concurrent reader without O_DIRECT > concurrent reader without O_DIRECT <=== ??? > sequential reader with O_DIRECT > sequential reader without O_DIRECT > > The lines marked "???" are unbelievable, due to the src/splice-test.c > only calls printf to output that message once in main function. So > Why splice-test prints that message twice sometimes? It seems related > with the "-r" option, due to the test lines without "-r" option only > print one line each time running. > > A stanger thing is this "double output" issue only can be triggered by > running g/591, can't reproduce it by running splice-test manually. Huh. I wonder.... > diff --git a/src/splice-test.c b/src/splice-test.c > index 2f1ba2ba..e6ae6fca 100644 > --- a/src/splice-test.c > +++ b/src/splice-test.c > @@ -143,6 +143,7 @@ int main(int argc, char *argv[]) > printf("%s reader %s O_DIRECT\n", > do_splice == do_splice1 ? "sequential" : "concurrent", > (open_flags & O_DIRECT) ? "with" : "without"); > + fflush(stdout); Yeah, ok, stdout output is usually line buffered. That printf() statement has a "\n" on the end of it, so it should be flushing immediately, and that's what you are seeing when it is run from the command line. Hmmmm. I wonder if the redirect to an output file (or pipe) is changing the buffering mode because stdout no longer points to a tty? # src/xfstests-dev/src/splice-test -r /mnt/test/a concurrent reader with O_DIRECT # src/xfstests-dev/src/splice-test -r /mnt/test/a | less concurrent reader with O_DIRECT concurrent reader with O_DIRECT # Yup. # man setbuf .... Normally all files are block buffered. If a stream refers to a terminal (as stdout normally does), it is line buffered. The standard error stream stderr is always unbuffered by default. Yeah, so the stdout redirection that fstests does is exactly what is changing the behaviour. Ok, so the correct way to fix this is to add: setlinebuf(stdout); before any printf() output to ensure that it is correctly line buffered no matter what the output redirection does with stdout. Cheers, Dave.
On Mon, May 30, 2022 at 10:44:52AM +1000, Dave Chinner wrote: > On Sun, May 29, 2022 at 06:55:03PM +0800, Zorro Lang wrote: > > In generic/591.out expects below output: > > concurrent reader with O_DIRECT > > concurrent reader with O_DIRECT <=== ??? > > concurrent reader without O_DIRECT > > concurrent reader without O_DIRECT <=== ??? > > sequential reader with O_DIRECT > > sequential reader without O_DIRECT > > > > The lines marked "???" are unbelievable, due to the src/splice-test.c > > only calls printf to output that message once in main function. So > > Why splice-test prints that message twice sometimes? It seems related > > with the "-r" option, due to the test lines without "-r" option only > > print one line each time running. > > > > A stanger thing is this "double output" issue only can be triggered by > > running g/591, can't reproduce it by running splice-test manually. > > Huh. I wonder.... > > > diff --git a/src/splice-test.c b/src/splice-test.c > > index 2f1ba2ba..e6ae6fca 100644 > > --- a/src/splice-test.c > > +++ b/src/splice-test.c > > @@ -143,6 +143,7 @@ int main(int argc, char *argv[]) > > printf("%s reader %s O_DIRECT\n", > > do_splice == do_splice1 ? "sequential" : "concurrent", > > (open_flags & O_DIRECT) ? "with" : "without"); > > + fflush(stdout); > > Yeah, ok, stdout output is usually line buffered. That printf() > statement has a "\n" on the end of it, so it should be flushing > immediately, and that's what you are seeing when it is run from the > command line. > > Hmmmm. I wonder if the redirect to an output file (or pipe) is > changing the buffering mode because stdout no longer points to a > tty? > > # src/xfstests-dev/src/splice-test -r /mnt/test/a > concurrent reader with O_DIRECT > # src/xfstests-dev/src/splice-test -r /mnt/test/a | less > concurrent reader with O_DIRECT > concurrent reader with O_DIRECT > # > > Yup. > > # man setbuf > .... > Normally all files are block buffered. If a stream refers > to a terminal (as stdout normally does), it is line > buffered. The standard error stream stderr is always > unbuffered by default. > > Yeah, so the stdout redirection that fstests does is exactly what is > changing the behaviour. > > Ok, so the correct way to fix this is to add: > > setlinebuf(stdout); > > before any printf() output to ensure that it is correctly line > buffered no matter what the output redirection does with stdout. Wow, that's it! You reveal the root cause of this issue :) Thanks, Zorro > > Cheers, > > Dave. > -- > Dave Chinner > david@fromorbit.com >
diff --git a/src/splice-test.c b/src/splice-test.c index 2f1ba2ba..e6ae6fca 100644 --- a/src/splice-test.c +++ b/src/splice-test.c @@ -143,6 +143,7 @@ int main(int argc, char *argv[]) printf("%s reader %s O_DIRECT\n", do_splice == do_splice1 ? "sequential" : "concurrent", (open_flags & O_DIRECT) ? "with" : "without"); + fflush(stdout); buffer = memalign(SECTOR_SIZE, BUFFER_SIZE); if (buffer == NULL) diff --git a/tests/generic/591.out b/tests/generic/591.out index d61811ee..e9fffd1d 100644 --- a/tests/generic/591.out +++ b/tests/generic/591.out @@ -1,7 +1,5 @@ QA output created by 591 concurrent reader with O_DIRECT -concurrent reader with O_DIRECT -concurrent reader without O_DIRECT concurrent reader without O_DIRECT sequential reader with O_DIRECT sequential reader without O_DIRECT
In generic/591.out expects below output: concurrent reader with O_DIRECT concurrent reader with O_DIRECT <=== ??? concurrent reader without O_DIRECT concurrent reader without O_DIRECT <=== ??? sequential reader with O_DIRECT sequential reader without O_DIRECT The lines marked "???" are unbelievable, due to the src/splice-test.c only calls printf to output that message once in main function. So Why splice-test prints that message twice sometimes? It seems related with the "-r" option, due to the test lines without "-r" option only print one line each time running. A stanger thing is this "double output" issue only can be triggered by running g/591, can't reproduce it by running splice-test manually. By checking the code of splice-test.c, I found a "fork()" in it, and it'll be called if the '-r' option is specified. So I suspect the redundant output come from the child process. By the help of strace tool, I got: 10554 execve("/root/git/xfstests/src/splice-test", ["/root/git/xfstests/src/splice-te"..., "-r", "/mnt/test/a"], 0x7ffcabc2c0a8 /* 202 vars */) = 0 ... 10554 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f937f5d5a10) = 10555 ... 10555 read(4, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 512) = 512 10555 write(1, "concurrent reader with O_DIRECT\n", 32) = 32 10555 exit_group(0) = ? 10555 +++ exited with 0 +++ 10554 <... wait4 resumed>NULL, 0, NULL) = 10555 10554 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=10555, si_uid=0, si_status=0, si_utime=0, si_stime=1} --- 10554 unlink("/mnt/test/a") = 0 10554 write(1, "concurrent reader with O_DIRECT\n", 32) = 32 10554 exit_group(0) = ? 10554 +++ exited with 0 +++ We can see the "concurrent reader with O_DIRECT\n" be printed by parent process 10554 and child process 10555 separately. As the output from child is unexpected and unstable. So I think we shouldn't use it as golden image. So I add a "fflush(stdout)" to clear the output buffer of parent process before forking a child. Then correct the generic/591.out. Signed-off-by: Zorro Lang <zlang@kernel.org> --- src/splice-test.c | 1 + tests/generic/591.out | 2 -- 2 files changed, 1 insertion(+), 2 deletions(-)