Bugzilla – Bug 1219262
LTP: dio_append.c freeze on a wait system call on build 50.1
Last modified: 2024-02-12 16:14:54 UTC
## Observation openQA test in scenario sle-15-SP6-Online-s390x-ltp_aiodio_part4@s390x-kvm fails in [ADI000](https://openqa.suse.de/tests/13372268/modules/ADI000/steps/7) Name : kernel-default Version : 6.4.0 Release : 150600.5.1 Architecture: s390x Install Date: Fri Jan 26 22:03:16 2024 Group : System/Kernel Size : 92678455 License : GPL-2.0-only Signature : RSA/SHA256, Fri Jan 26 14:17:55 2024, Key ID 70af9e8139db7c82 Source RPM : kernel-default-6.4.0-150600.5.1.nosrc.rpm Build Date : Fri Jan 26 14:12:00 2024 Build Host : s390zl33 Relocations : (not relocatable) Packager : https://www.suse.com/ Vendor : SUSE LLC <https://www.suse.com/> URL : https://www.kernel.org/ Summary : The Standard Kernel Description : The standard kernel for both uniprocessor and multiprocessor systems. strace show process stop on wait call forever. susetest:/opt # strace ./ltp/testcases/bin/dio_append execve("./ltp/testcases/bin/dio_append", ["./ltp/testcases/bin/dio_append"], 0x3ffcdffa140 /* 53 vars */) = 0 brk(NULL) = 0x2aa0dd90000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=32975, ...}) = 0 mmap(NULL, 32975, PROT_READ, MAP_PRIVATE, 3, 0) = 0x3ffb2e00000 close(3) = 0 openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\2\1\3\0\0\0\0\0\0\0\0\0\3\0\26\0\0\0\1\0\0\0\0\0\3A\330"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=2222472, ...}) = 0 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3ffb2ef9000 mmap(NULL, 1952456, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3ffb2b00000 mmap(0x3ffb2cca000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c9000) = 0x3ffb2cca000 mmap(0x3ffb2cd0000, 51912, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3ffb2cd0000 close(3) = 0 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3ffb2ef7000 set_tid_address(0x3ffb2efa890) = 3032 set_robust_list(0x3ffb2efa8a0, 24) = 0 rseq(0x3ffb2efaee0, 0x20, 0, 0xb2ff0fff) = 0 mprotect(0x3ffb2cca000, 16384, PROT_READ) = 0 mprotect(0x2aa0bdb6000, 8192, PROT_READ) = 0 mprotect(0x3ffb2eab000, 8192, PROT_READ) = 0 prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0 munmap(0x3ffb2e00000, 32975) = 0 getpid() = 3032 openat(AT_FDCWD, "/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 3 read(3, "0\n", 1024) = 2 close(3) = 0 getrandom("\xb1\x6f\x8d\x34\xea\x90\xe1\x02", 8, GRND_NONBLOCK) = 8 brk(NULL) = 0x2aa0dd90000 brk(0x2aa0ddb1000) = 0x2aa0ddb1000 openat(AT_FDCWD, "/proc/meminfo", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 read(3, "MemTotal: 803420 kB\nMemF"..., 1024) = 1024 close(3) = 0 openat(AT_FDCWD, "/proc/meminfo", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 read(3, "MemTotal: 803420 kB\nMemF"..., 1024) = 1024 close(3) = 0 access("/dev/shm", F_OK) = 0 getpid() = 3032 openat(AT_FDCWD, "/dev/shm/ltp_dio_append_3032", O_RDWR|O_CREAT|O_EXCL, 0600) = 3 chmod("/dev/shm/ltp_dio_append_3032", 0666) = 0 ftruncate(3, 4096) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x3ffb2e00000 unlink("/dev/shm/ltp_dio_append_3032") = 0 close(3) = 0 mkdir("/tmp/LTP_diowbJjbT", 0700) = 0 getgid() = 0 chown("/tmp/LTP_diowbJjbT", -1, 0) = 0 chmod("/tmp/LTP_diowbJjbT", 0777) = 0 getcwd("/opt", 4096) = 5 chdir("/tmp/LTP_diowbJjbT") = 0 access("/proc/self/oom_score_adj", F_OK) = 0 access("/proc/3032/oom_score_adj", F_OK) = 0 openat(AT_FDCWD, "/proc/3032/oom_score_adj", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 write(3, "-1000", 5) = 5 close(3) = 0 openat(AT_FDCWD, "/proc/3032/oom_score_adj", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 read(3, "-1000\n", 1024) = 6 close(3) = 0 rt_sigaction(SIGALRM, {sa_handler=0x2aa0bd91b88, sa_mask=[ALRM], sa_flags=SA_RESTART}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigaction(SIGUSR1, {sa_handler=0x2aa0bd91b00, sa_mask=[USR1], sa_flags=SA_RESTART}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0 write(2, "tst_test.c:1709: \33[1;34mTINFO: \33"..., 57tst_test.c:1709: TINFO: LTP version: 20230929 ) = 57 write(2, "tst_test.c:1595: \33[1;34mTINFO: \33"..., 65tst_test.c:1595: TINFO: Timeout per run is 0h 30m 30s ) = 65 rt_sigaction(SIGINT, {sa_handler=0x2aa0bd91b38, sa_mask=[INT], sa_flags=SA_RESTART}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigaction(SIGTERM, {sa_handler=0x2aa0bd91b38, sa_mask=[TERM], sa_flags=SA_RESTART}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 alarm(1830) = 0 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x3ffb2efa890) = 3033 wait4(3033, 0x3ffc7479d60, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=3033, si_uid=0} --- alarm(1830) = 1830 sigreturn({mask=[]}) = 3033 wait4(3033, tst_test.c:1347: TINFO: btrfs is supported by the test 0x3ffc7479d60, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=3033, si_uid=0} --- alarm(1830) = 1830 sigreturn({mask=[]}) = 3033 wait4(3033, dio_append.c:73: TINFO: Parent append to file <<<<<<<< common.h:108: TINFO: child 3040 reading file common.h:108: TINFO: child 3041 reading file common.h:108: TINFO: child 3042 reading file common.h:108: TINFO: child 3043 reading file common.h:108: TINFO: child 3044 reading file common.h:108: TINFO: child 3045 reading file common.h:108: TINFO: child 3046 reading file common.h:108: TINFO: child 3047 reading file common.h:108: TINFO: child 3048 reading file common.h:108: TINFO: child 3049 reading file common.h:108: TINFO: child 3039 reading file common.h:108: TINFO: child 3038 reading file common.h:108: TINFO: child 3037 reading file common.h:108: TINFO: child 3036 reading file common.h:108: TINFO: child 3035 reading file dio_append.c:83: TPASS: All bytes read were zeroed Build 49.1 result is good, i also attach the strace log in attachment for 49.1.
Created attachment 872241 [details] strace log 49.1
This seems to be a test issue, related with a synchronization problems between parent and children. By adding a usleep(10) at the end of the reading process, test passes without problems. Probably children now are way faster to process I/O syscalls, locking parent exit and timing out the test in openQA. I will send a patch for it.
Sent a patch to fix this https://patchwork.ozlabs.org/project/ltp/patch/20240129101448.14463-1-andrea.cervesato@suse.de/
(In reply to WEI GAO from comment #0) > strace show process stop on wait call forever. This is the trace of the watchdog process which forks() the actual tests process and then waits for it to exit or time out. You need to use strace -f to capture a useful trace.
And for gdb: set follow-fork-mode child (https://github.com/linux-test-project/ltp?tab=readme-ov-file#debugging-with-gdb)
Ok I found it: there's a problem with parent implementation. Basically the test is calling unlink() just after telling all children that they should stop. What happens is that when at least one child is pending and processing lseek(), openat() syscall keeps failing with -ENOENT because of unlink(). We should take a look at the lseek() implementation or openat() implementation closer to check if there's a bug around there, because it's strange that -ENOENT is not propagated through lseek(). The fix for the test is easy and it's something we have to add anyway. At dio_append.c:85, we need to wait for children to end just before removing the file. *run_child = 0; tst_reap_children(); <----- SAFE_UNLINK(filename);
(In reply to Andrea Cervesato from comment #6) > Ok I found it: there's a problem with parent implementation. Basically the > test is calling unlink() just after telling all children that they should > stop. What happens is that when at least one child is pending and processing > lseek(), openat() syscall keeps failing with -ENOENT because of unlink(). We > should take a look at the lseek() implementation or openat() implementation > closer to check if there's a bug around there, because it's strange that > -ENOENT is not propagated through lseek(). > > The fix for the test is easy and it's something we have to add anyway. > At dio_append.c:85, we need to wait for children to end just before removing > the file. > > *run_child = 0; > > tst_reap_children(); <----- > > SAFE_UNLINK(filename); I also suggest do not use while loop for open syscall at same time then we have no risk on dead loop. @@ -102,8 +103,9 @@ static inline void io_read_eof(const char *filename, volatile int *run_child) int fd; int r; - while ((fd = open(filename, O_RDONLY, 0666)) < 0) - usleep(100); + fd = SAFE_OPEN(filename, O_RDONLY, 0666);
(In reply to Andrea Cervesato from comment #6) > Ok I found it: there's a problem with parent implementation. Basically the > test is calling unlink() just after telling all children that they should > stop. What happens is that when at least one child is pending and processing > lseek(), openat() syscall keeps failing with -ENOENT because of unlink(). We > should take a look at the lseek() implementation or openat() implementation > closer to check if there's a bug around there, because it's strange that > -ENOENT is not propagated through lseek(). I've tried to reproduce the issue on SLE-15SP5 using the latest LTP git and everything passed: https://openqa.suse.de/tests/13375452#step/ADI000/8 For now, I'd assume this issue is a kernel bug. (In reply to WEI GAO from comment #7) > I also suggest do not use while loop for open syscall at same time then we > have no risk on dead loop. > @@ -102,8 +103,9 @@ static inline void io_read_eof(const char *filename, > volatile int *run_child) > int fd; > int r; > > - while ((fd = open(filename, O_RDONLY, 0666)) < 0) > - usleep(100); > + fd = SAFE_OPEN(filename, O_RDONLY, 0666); This change would break the test because the test file does not exist when io_read_eof() gets called.
I guess the easiest solution would be: diff --git a/testcases/kernel/io/ltp-aiodio/common.h b/testcases/kernel/io/ltp-aiodio/common.h index 200bbe18e..159bb25e4 100644 --- a/testcases/kernel/io/ltp-aiodio/common.h +++ b/testcases/kernel/io/ltp-aiodio/common.h @@ -62,8 +62,11 @@ static inline void io_read(const char *filename, int filesize, volatile int *run int i; int r; - while ((fd = open(filename, O_RDONLY, 0666)) < 0) + while ((fd = open(filename, O_RDONLY, 0666)) < 0) { + if (!*run_child) + return; usleep(100); + } tst_res(TINFO, "child %i reading file", getpid()); @@ -102,8 +105,11 @@ static inline void io_read_eof(const char *filename, volatile int *run_child) int fd; int r; - while ((fd = open(filename, O_RDONLY, 0666)) < 0) + while ((fd = open(filename, O_RDONLY, 0666)) < 0) { + if (!*run_child) + return; usleep(100); + } tst_res(TINFO, "child %i reading file", getpid()); With that the children that haven't had chance to run would exit the retry loop if the parent had signaled that they should exit. Also on my machine the test runs for 0.1s and for 16 children, that means that even if there were not any other processes running on the machine it would be understandable that one or two children wouldn't get to run until the parent is done. Quite possibly we should change the test so that the children have chance to run, maybe we should increase the number of appends by 10, since the test was written in the times where I/O was order of magnitude or even two smaller.
Fixed by https://patchwork.ozlabs.org/project/ltp/patch/20240131100018.15767-2-andrea.cervesato@suse.de/ Waiting for a new build to close ticket.
The bug has been fixed. Ticket can be closed. Thanks
Problem fixed.