Hello,
We are doing LTP validation on HiFive Unleashed (Yocto linux 5.4.3). Can someone please help us understand this test failure? Is this expected?
Testcase: min_free_kbytes
Error on HiFive Unleashed:
https://github.com/linux-test-project/ltp/issues/642
min_free_kbytes.c:134: FAIL: child unexpectedly failed: 139.
Program terminated with signal SIGSEGV, Segmentation fault.
Conversation with LTP on this:
Email Conversation with LTP:
Hi,
i am running min_free_kbytes test,6 test cases are failing with error message min_free_kbytes.c:134: FAIL: child unexpectedly failed: 139.
Please find my strace output(Parent)
root@exaleapsemi:~/pankaj_ltp_new/ltp/testcases/kernel/mem/tunable# strace ./min_free_kbytes
execve("./min_free_kbytes", ["./min_free_kbytes"], 0x3fffb45c80 /* 15 vars */) = 0
brk(NULL) = 0x2c000
uname({sysname=“Linux”, nodename=“exaleapsemi”, …}) = 0
faccessat(AT_FDCWD, “/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=66866, …}) = 0
mmap(NULL, 66866, PROT_READ, MAP_PRIVATE, 3, 0) = 0x3fd7669000
close(3) = 0
openat(AT_FDCWD, “/usr/lib/libnuma.so.1”, O_RDONLY|O_CLOEXEC) = 3
read(3, “\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\363\0\1\0\0\0\2002\0\0\0\0\0\0”…, 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=35664, …}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3fd7667000
mmap(NULL, 54992, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3fd7659000
mprotect(0x3fd7660000, 4096, PROT_NONE) = 0
mmap(0x3fd7661000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x3fd7661000
mmap(0x3fd7663000, 14032, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3fd7663000
close(3) = 0
openat(AT_FDCWD, “/lib/libpthread.so.0”, O_RDONLY|O_CLOEXEC) = 3
read(3, “\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\363\0\1\0\0\0\204p\0\0\0\0\0\0”…, 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=89264, …}) = 0
mmap(NULL, 107632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3fd763e000
mprotect(0x3fd7652000, 4096, PROT_NONE) = 0
mmap(0x3fd7653000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14000) = 0x3fd7653000
mmap(0x3fd7655000, 13424, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3fd7655000
close(3) = 0
openat(AT_FDCWD, “/lib/libc.so.6”, O_RDONLY|O_CLOEXEC) = 3
read(3, “\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0\363\0\1\0\0\0\2005\2\0\0\0\0\0”…, 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1061392, …}) = 0
mmap(NULL, 1072656, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3fd7538000
mmap(0x3fd7635000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xfc000) = 0x3fd7635000
mmap(0x3fd763b000, 11792, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3fd763b000
close(3) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3fd7536000
mprotect(0x3fd7635000, 12288, PROT_READ) = 0
mprotect(0x3fd7653000, 4096, PROT_READ) = 0
mprotect(0x3fd7661000, 4096, PROT_READ) = 0
mprotect(0x28000, 4096, PROT_READ) = 0
mprotect(0x3fd7693000, 4096, PROT_READ) = 0
munmap(0x3fd7669000, 66866) = 0
set_tid_address(0x3fd75360e0) = 33300
set_robust_list(0x3fd75360f0, 24) = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x3fd7644c52, sa_mask=[], sa_flags=SA_SIGINFO}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x3fd7644cd2, sa_mask=[], sa_flags=SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
brk(NULL) = 0x2c000
brk(0x4d000) = 0x4d000
openat(AT_FDCWD, “/proc/self/status”, O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, …}) = 0
read(3, “Name:\tmin_free_kbytes\nUmask:\t002”…, 1024) = 960
read(3, “”, 1024) = 0
close(3) = 0
get_mempolicy(0x3fffe9fb6c, 0x2c920, 33, NULL, 0) = -1 ENOSYS (Function not implemented)
openat(AT_FDCWD, “/sys/devices/system/node”, O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or directory)
sched_getaffinity(0, 512, [0, 1, 2, 3]) = 8
openat(AT_FDCWD, “/sys/devices/system/cpu”, O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=0, …}) = 0
getdents64(3, /* 14 entries */, 32768) = 400
getdents64(3, /* 0 entries */, 32768) = 0
close(3) = 0
openat(AT_FDCWD, “/proc/self/status”, O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, …}) = 0
read(3, “Name:\tmin_free_kbytes\nUmask:\t002”…, 1024) = 960
read(3, “”, 1024) = 0
close(3) = 0
getpid() = 33300
geteuid() = 0
faccessat(AT_FDCWD, “/dev/shm”, F_OK) = 0
getpid() = 33300
openat(AT_FDCWD, “/dev/shm/ltp_min_free_kbytes_33300”, O_RDWR|O_CREAT|O_EXCL, 0600) = 3
fchmodat(AT_FDCWD, “/dev/shm/ltp_min_free_kbytes_33300”, 0666) = 0
ftruncate(3, 4096) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x3fd7679000
unlinkat(AT_FDCWD, “/dev/shm/ltp_min_free_kbytes_33300”, 0) = 0
close(3) = 0
rt_sigaction(SIGALRM, {sa_handler=0x14f74, sa_mask=[ALRM], sa_flags=SA_RESTART}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR1, {sa_handler=0x14e58, 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:1206: \33[1;34mINFO: \33[”…, 62tst_test.c:1206: INFO: Timeout per run is disabled
) = 62
rt_sigaction(SIGINT, {sa_handler=0x14f38, sa_mask=[INT], sa_flags=SA_RESTART}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x3fd75360e0) = 33301
wait4(33301, 0x3fffe9f9c8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
— SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=33301, si_uid=0} —
setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}) = 0
rt_sigreturn({mask=[]}) = 33301
wait4(33301, mem.c:817: INFO: set overcommit_memory to 2
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 7877544 kB before eatup mem
memfree is 4038116 kB after eatup mem
mem.c:817: INFO: set min_free_kbytes to 327288
memfree is 7863212 kB before eatup mem
memfree is 4053228 kB after eatup mem
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 7863264 kB before eatup mem
memfree is 4057852 kB after eatup mem
mem.c:817: INFO: set overcommit_memory to 0
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 7863108 kB before eatup mem
min_free_kbytes.c:173: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 327288
memfree is 8032744 kB before eatup mem
min_free_kbytes.c:173: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 8034384 kB before eatup mem
min_free_kbytes.c:173: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set overcommit_memory to 1
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 8050968 kB before eatup mem
min_free_kbytes.c:155: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 327288
memfree is 8052860 kB before eatup mem
min_free_kbytes.c:155: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 8043428 kB before eatup mem
min_free_kbytes.c:155: FAIL: child unexpectedly failed: 11
min_free_kbytes.c:103: PASS: min_free_kbytes test pass
mem.c:817: INFO: set min_free_kbytes to 163644
mem.c:817: INFO: set overcommit_memory to 1
0x3fffe9f9c8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
— SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=33301, si_uid=0} —
— SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=33301, si_uid=0, si_status=0, si_utime=0, si_stime=0} —
setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}) = 0
rt_sigreturn({mask=[]}) = 33301
wait4(33301, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 33301
setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}) = 0
rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[INT], sa_flags=SA_RESTART}, {sa_handler=0x14f38, sa_mask=[INT], sa_flags=SA_RESTART}, 8) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), …}) = 0
write(1, “\n”, 1
) = 1
write(1, “Summary:\n”, 9Summary:
) = 9
write(1, “passed 1\n”, 11passed 1
) = 11
write(1, “failed 6\n”, 11failed 6
) = 11
write(1, “skipped 0\n”, 11skipped 0
) = 11
write(1, “warnings 0\n”, 11warnings 0
) = 11
faccessat(AT_FDCWD, “/dev/shm/ltp_min_free_kbytes_33300”, F_OK) = -1 ENOENT (No such file or directory)
msync(0x3fd7679000, 4096, MS_SYNC) = 0
munmap(0x3fd7679000, 4096) = 0
exit_group(1) = ?
+++ exited with 1 +++
//*************************** This is the result of strace -f************************/
pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18a08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18908000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18808000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18708000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18608000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18508000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18408000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18308000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18208000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18108000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e18008000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17f08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17e08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17d08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17c08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17b08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17a08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17908000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17808000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17708000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17608000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17508000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17408000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17308000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17208000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17108000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e17008000
[ pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e16f08000
[pid 48522] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e16e08000
Segmentation fault
root@exaleapsemi:~/pankaj_ltp_new/ltp/testcases/kernel/mem/tunable# min_free_kbytes.c:173: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 8048240 kB before eatup mem
min_free_kbytes.c:173: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set overcommit_memory to 1
mem.c:817: INFO: set min_free_kbytes to 327288
memfree is 8047972 kB before eatup mem
min_free_kbytes.c:155: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 654576
memfree is 8047800 kB before eatup mem
min_free_kbytes.c:155: FAIL: child unexpectedly failed: 11
mem.c:817: INFO: set min_free_kbytes to 163644
memfree is 8039996 kB before eatup mem
min_free_kbytes.c:155: FAIL: child unexpectedly failed: 11
min_free_kbytes.c:103: PASS: min_free_kbytes test pass
mem.c:817: INFO: set min_free_kbytes to 327288
mem.c:817: INFO: set overcommit_memory to 1
Summary:
passed 1
failed 7
skipped 0
warnings 0
Response from LTP Forum:
i am attaching the test result
Output is unusual, status codes suggest child running into SIGSEGV and SIGILL at some
point after eatup_mem(). Did you try to run this with gdb, strace or look at core files?
Hi Jan,
> i have tried to collect the core through GDB this is the result i found??what
> i should conclude from this??
root@exaleapsemi:~/pankaj_ltpn/ltp/testcases/kernel/mem/tunable# gdb ./min_free_kbytes core.378
GNU gdb (GDB) 8.3.1
Copyright © 2019 Free Software Foundation, Inc.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type “show copying” and “show warranty” for details.
This GDB was configured as “riscv64-oe-linux”.
Type “show configuration” for configuration details.
For bug reporting instructions, please see:
Find the GDB manual and other documentation resources online at:
For help, type “help”.
Type “apropos word” to search for commands related to “word”…??
Reading symbols from ./min_free_kbytes…
[New LWP 378]
[Thread debugging using libthread_db enabled]
Using host libthread_db library “/lib/libthread_db.so.1”.
Core was generated by `./min_free_kbytes’.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x0000003fe1713b92 in __vfscanf_internal (s=0x23000, format=<optimized out>, argptr=<optimized out>, mode_flags=<optimized out>) at vfscanf-internal.c:345
Response from LTP:
Can you paste the output of backtrace? (‘bt’ command in gdb)–>
gdb) bt
> #0 0x0000003fe1713b92 in __vfscanf_internal (s=0x23000, format=<optimized
> out>, argptr=<optimized out>, mode_flags=<optimized out>) at
> vfscanf-internal.c:345
> Backtrace stopped: Cannot access memory at address 0xfffffffffffffff9
(gdb) where
> #0 0x0000003fe1713b92 in __vfscanf_internal (s=0x23000, format=<optimized
> out>, argptr=<optimized out>, mode_flags=<optimized out>) at
> vfscanf-internal.c:345
> Backtrace stopped: Cannot access memory at address 0xfffffffffffffff9
>
> (gdb) info registers
> ra 0x16438 0x16438 <safe_waitpid+40>
> sp 0x3fffd94850 0x3fffd94850
> gp 0x29f10 0x29f10 <ipc_path+544>
> tp 0x3fe16cd720 0x3fe16cd720
> t0 0xffffffffffffffff -1
> t1 0x1366c 79468
> t2 0x1000 4096
> fp 0x1 0x1
> s1 0x180 384
> a0 0x180 384
> a1 0x3fffd948c4 274875369668
> a2 0xa 10
> a3 0x0 0
> a4 0x3fffd948c4 274875369668
> a5 0xffffffffffffffff -1
> a6 0x1 1
> a7 0x104 260
> s2 0x3fffd948c4 274875369668
> s3 0xa 10
> s4 0x79 121
> s5 0x3fe17e6008 274366095368
> s6 0x21ad0 137936
> s7 0x22000 139264
> s8 0x22000 139264
> s9 0x22000 139264
> s10 0x23000 143360
> s11 0x1fed70 2092400
> t3 0x3fe17e5790 274366093200
> t4 0x3fe17a2070 274365816944
> t5 0x3fe17a2970 274365819248
> t6 0x5 5
> pc 0x3fe1713b92 0x3fe1713b92 <__vfscanf_internal+1126>
> (gdb)
>
Response from LTP
hich is unfortunate.
Only place I see child reaching vfscanf is via check_monitor -> get_sys_tune,
but per test output it’s not check_monitor child, but eatup_mem one.
I don’t see why it would crash here, and why it happens on RISCV only.
I can only recommend to try simplify the testcase to see what triggers it.
Is this the only LTP test you see crashing?
Is it built natively on RISCV or is it cross-compiled in other environment?