clock_settime/clock_settime_8-1: failed occasionally

[ZhangYet]

I am running ltp-timer test in lava. I found that the clock_settime test case failed occasionally.

For example, this is a test log from kernelci.org: https://storage.kernelci.org/rt-stable/v5.15-rt/v5.15.25-rt33/arm/multi_v7_defconfig+preempt_rt/gcc-10/lab-collabora/ltp-timers-rk3288-veyron-jaq.txt

I run the test case in my qemu VM:

kernel version: 5.15
qemu version: QEMU emulator version 4.2.1 (Debian 1:4.2-3ubuntu6.19)
rootfs: https://storage.kernelci.org/images/rootfs/debian/bullseye-ltp/20220311.1/amd64/rootfs.cpio.gz
ltp version: 20180515, f2ba2a1

I started the qemu VM as below:

qemu-system-x86_64 -cpu host -enable-kvm -nographic -net nic,model=virtio,macaddr=52:54:00:12:34:58 -net user -m 4096 -monitor none -smp 4 -kernel bzImage -append console=ttyS0,115200 root=/dev/ram0 -initrd bullseye.cpio.gz -drive format=qcow2,file=overlay4.qcow2,media=disk,if=ide,id=lavatest

I think I reproduce the same problem in #478

I have run

for i in `seq 1 10`; do ./clock_settime_8-1.run-test ; done

in the qemu VM. It passed sometimes. I added some printf in it.

/lava/lava # for i in `seq 1 10`; do ./clock_settime_8-1.run-test ; done
in parent process: 1647856885 (add some log in the 
in parent process: tsT0: 1647856885
in child process: 1647856885
in parent process after sleep: tsT0: 1647856885
in parent process after settime: tsT0: 1647856885
in child process: tsT0: 1647856885
expectedsec: 1647856888, tsend: 1647856890
Ended too late.  1647856890 >> 1647856888
================Test FAILED
in parent process: 1647856892
in parent process: tsT0: 1647856892
in child process: 1647856892
in parent process after sleep: tsT0: 1647856892
in parent process after settime: tsT0: 1647856892
in child process: tsT0: 1647856892
expectedsec: 1647856895, tsend: 1647856895
================Test PASSED
in parent process: 1647856897
in parent process: tsT0: 1647856897
in child process: 1647856897
in parent process after sleep: tsT0: 1647856897
in parent process after settime: tsT0: 1647856897
in child process: tsT0: 1647856897
expectedsec: 1647856900, tsend: 1647856900
================Test PASSED
in parent process: 1647856902
in parent process: tsT0: 1647856902
in child process: 1647856902
in parent process after sleep: tsT0: 1647856902
in parent process after settime: tsT0: 1647856902
in child process: tsT0: 1647856902
expectedsec: 1647856905, tsend: 1647856905
================Test PASSED
in parent process: 1647856907
in parent process: tsT0: 1647856907
in child process: 1647856907
in parent process after sleep: tsT0: 1647856907
in parent process after settime: tsT0: 1647856907
in child process: tsT0: 1647856907
expectedsec: 1647856910, tsend: 1647856910
================Test PASSED
in parent process: 1647856912
in parent process: tsT0: 1647856912
in child process: 1647856912
in parent process after sleep: tsT0: 1647856912
in parent process after settime: tsT0: 1647856912
in child process: tsT0: 1647856912
expectedsec: 1647856915, tsend: 1647856915
================Test PASSED
in parent process: 1647856917
in parent process: tsT0: 1647856917
in child process: 1647856917
in parent process after sleep: tsT0: 1647856917
in parent process after settime: tsT0: 1647856917
in child process: tsT0: 1647856917
expectedsec: 1647856920, tsend: 1647856920
================Test PASSED
in child process: 1647856922
in parent process: 1647856922
in parent process: tsT0: 1647856922
in parent process after sleep: tsT0: 1647856922
in parent process after settime: tsT0: 1647856922
in child process: tsT0: 1647856922
expectedsec: 1647856925, tsend: 1647856925
================Test PASSED
in parent process: 1647856927
in parent process: tsT0: 1647856927
in child process: 1647856927
in parent process after sleep: tsT0: 1647856927
in parent process after settime: tsT0: 1647856927
in child process: tsT0: 1647856927
expectedsec: 1647856930, tsend: 1647856930
================Test PASSED
in parent process: 1647856932
in parent process: tsT0: 1647856932
in child process: 1647856932
in parent process after sleep: tsT0: 1647856932
in parent process after settime: tsT0: 1647856932
in child process: tsT0: 1647856932
expectedsec: 1647856935, tsend: 1647856935
================Test PASSED

[metan-ucw]

Looking at the test code, there are several things that can cause the difference. First of all it completely ignores tv_nsec fields of the timespec structure, so if we are unlucky we may end up with tsT0 where tv_nsec is really close to 1 second and the same for tsend.tv_sec, the rounding errors may accumulate in a wrong way and cause the test failure. We do have a timespec_nsec_diff() function in the open_posix_testsuite/include/timespec.h we should use that in the test to get a difference between tsT0 and tsend then check if that is between NSEC_IN_SEC * (SLEEPSEC-SMALLTIME) and NSEC_IN_SEC * (SLEEPSEC-SMALLTIME+ACCEPTABLEDELTA). That should ideally get rid of the rounding errors.

[ZhangYet]

@metan-ucw see #927

And the output in VM is:

/lava/lava # ./clock_settime_8-1.run-test
diffnano: 5024780631, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944328 >> 1647944326
Test FAILED
/lava/lava # for i in `seq 1 10`; do ./clock_settime_8-1.run-test ; done
diffnano: 5002171203, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944383 >> 1647944381
Test FAILED
diffnano: 5002511924, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944388 >> 1647944386
Test FAILED
diffnano: 5001937618, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944393 >> 1647944391
Test FAILED
diffnano: 5001433654, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944398 >> 1647944396
Test FAILED
diffnano: 5000561416, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944403 >> 1647944401
Test FAILED
diffnano: 5000945590, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944408 >> 1647944406
Test FAILED
diffnano: 5000963849, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944413 >> 1647944411
Test FAILED
diffnano: 2999975247, >= 3000000000: 0, <= 4000000000: 1
Test PASSED
diffnano: 3000084044, >= 3000000000: 1, <= 4000000000: 1
Test PASSED
diffnano: 5002827602, >= 3000000000: 1, <= 4000000000: 0
Ended too late.  1647944428 >> 1647944426
Test FAILED

[metan-ucw]

That looks suspicious, the difference is either almost exactly 5 or 3 seconds. That looks like somehow the realtime clock wasn't adjusted during the time the child slept in clock_nanosleep(). That shouldn't really happen unless the machine is under heavy load.

[ZhangYet]

I used strace to monitor the syscall.
There were two clock_nanosleep resumed logs in the host machine. But only one in the VM.

strace output in the host machine:

23:12:46.181256 execve("./clock_settime_8-1.run-test", ["./clock_settime_8-1.run-test"], 0x7ffeb23e6d98 /* 14 vars */) = 0 <0.000367>
23:12:46.181928 brk(NULL)               = 0x562cc7a09000 <0.000029>
23:12:46.182036 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffec28a01d0) = -1 EINVAL (Invalid argument) <0.000020>
23:12:46.182354 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000042>
23:12:46.182476 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000026>
23:12:46.182560 fstat(3, {st_mode=S_IFREG|0644, st_size=67019, ...}) = 0 <0.000019>
23:12:46.182647 mmap(NULL, 67019, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f1b259ab000 <0.000029>
23:12:46.182727 close(3)                = 0 <0.000018>
23:12:46.182802 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000025>
23:12:46.182882 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360q\2\0\0\0\0\0"..., 832) = 832 <0.000020>
23:12:46.182957 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784 <0.000019>
23:12:46.183027 pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32 <0.000018>
23:12:46.183096 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\t\233\222%\274\260\320\31\331\326\10\204\276X>\263"..., 68, 880) = 68 <0.000018>
23:12:46.183167 fstat(3, {st_mode=S_IFREG|0755, st_size=2029224, ...}) = 0 <0.000018>
23:12:46.183238 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1b259a9000 <0.000021>
23:12:46.183313 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784 <0.000019>
23:12:46.183388 pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32 <0.000019>
23:12:46.183457 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\t\233\222%\274\260\320\31\331\326\10\204\276X>\263"..., 68, 880) = 68 <0.000019>
23:12:46.183548 mmap(NULL, 2036952, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f1b257b7000 <0.000120>
23:12:46.183725 mprotect(0x7f1b257dc000, 1847296, PROT_NONE) = 0 <0.000030>
23:12:46.183805 mmap(0x7f1b257dc000, 1540096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7f1b257dc000 <0.000035>
23:12:46.183898 mmap(0x7f1b25954000, 303104, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19d000) = 0x7f1b25954000 <0.000024>
23:12:46.183975 mmap(0x7f1b2599f000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f1b2599f000 <0.000024>
23:12:46.184059 mmap(0x7f1b259a5000, 13528, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f1b259a5000 <0.000022>
23:12:46.184145 close(3)                = 0 <0.000020>
23:12:46.184239 arch_prctl(ARCH_SET_FS, 0x7f1b259aa580) = 0 <0.000019>
23:12:46.184416 mprotect(0x7f1b2599f000, 12288, PROT_READ) = 0 <0.000027>
23:12:46.184500 mprotect(0x562cc5b98000, 4096, PROT_READ) = 0 <0.000023>
23:12:46.184621 mprotect(0x7f1b259e9000, 4096, PROT_READ) = 0 <0.000026>
23:12:46.184713 munmap(0x7f1b259ab000, 67019) = 0 <0.000041>
23:12:46.184876 getuid()                = 0 <0.000019>
23:12:46.184955 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace/src/strace: Process 46923 attached
, child_tidptr=0x7f1b259aa850) = 46923 <0.000176>
[pid 46922] 23:12:46.185228 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=2, tv_nsec=0},  <unfinished ...>
[pid 46923] 23:12:46.185284 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=5, tv_nsec=0},  <unfinished ...>
[pid 46922] 23:12:48.185529 <... clock_nanosleep resumed>0x7ffec28a0100) = 0 <2.000215>
[pid 46922] 23:12:48.185691 clock_settime(CLOCK_REALTIME, {tv_sec=1648048366, tv_nsec=184936122}) = 0 <0.000197>
[pid 46922] 23:12:46.185201 wait4(-1,  <unfinished ...>
[pid 46923] 23:12:49.184715 <... clock_nanosleep resumed>NULL) = 0 <5.000227>
[pid 46923] 23:12:49.185053 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0 <0.000169>
[pid 46923] 23:12:49.185524 brk(NULL)   = 0x562cc7a09000 <0.000039>
[pid 46923] 23:12:49.185701 brk(0x562cc7a2a000) = 0x562cc7a2a000 <0.000033>
[pid 46923] 23:12:49.185861 write(1, "diffnano: 2999894714, >= 3000000"..., 57diffnano: 2999894714, >= 3000000000: 0, <= 4000000000: 1
) = 57 <0.000034>
[pid 46923] 23:12:49.186058 exit_group(1) = ?
[pid 46923] 23:12:49.186525 +++ exited with 1 +++
23:12:49.186615 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0, NULL) = 46923 <3.001379>
23:12:49.186807 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=46923, si_uid=0, si_status=1, si_utime=0, si_stime=0} ---
23:12:49.187298 clock_settime(CLOCK_REALTIME, {tv_sec=1648048371, tv_nsec=187136636}) = 0 <0.004006>
23:12:51.191387 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0 <0.000148>
23:12:51.191860 brk(NULL)               = 0x562cc7a09000 <0.000146>
23:12:51.192222 brk(0x562cc7a2a000)     = 0x562cc7a2a000 <0.000150>
23:12:51.192599 write(1, "Test PASSED\n", 12Test PASSED
) = 12 <0.000155>
23:12:51.193152 exit_group(0)           = ?
23:12:51.193765 +++ exited with 0 +++

strace output in the VM:

15:11:21.591809 execve("./clock_settime_8-1.run-test", ["./clock_settime_8-1.run-test"], 0x7ffed26eaca8 /* 12 vars */) = 0 <0.001323>
15:11:21.613480 brk(NULL)               = 0x55a139c18000 <0.000246>
15:11:21.625078 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000280>
15:11:21.640664 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000314>
15:11:21.654453 fstat(3, {st_mode=S_IFREG|0644, st_size=9492, ...}) = 0 <0.000309>
15:11:21.667764 mmap(NULL, 9492, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6b006b6000 <0.000298>
15:11:21.681649 close(3)                = 0 <0.000231>
15:11:21.691184 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000263>
15:11:21.704936 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@n\2\0\0\0\0\0"..., 832) = 832 <0.000200>
15:11:21.721228 fstat(3, {st_mode=S_IFREG|0755, st_size=1839792, ...}) = 0 <0.000260>
15:11:21.734547 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6b006b4000 <0.000243>
15:11:21.751410 mmap(NULL, 1852680, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6b004ef000 <0.000253>
15:11:21.766025 mprotect(0x7f6b00514000, 1662976, PROT_NONE) = 0 <0.000365>
15:11:21.777756 mmap(0x7f6b00514000, 1355776, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7f6b00514000 <0.000335>
15:11:21.797762 mmap(0x7f6b0065f000, 303104, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x170000) = 0x7f6b0065f000 <0.000343>
15:11:21.818395 mmap(0x7f6b006aa000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ba000) = 0x7f6b006aa000 <0.000450>
15:11:21.839704 mmap(0x7f6b006b0000, 13576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6b006b0000 <0.000339>
15:11:21.860271 close(3)                = 0 <0.000290>
15:11:21.870633 arch_prctl(ARCH_SET_FS, 0x7f6b006b5580) = 0 <0.000433>
15:11:21.883291 mprotect(0x7f6b006aa000, 12288, PROT_READ) = 0 <0.000385>
15:11:21.895751 mprotect(0x55a138ebc000, 4096, PROT_READ) = 0 <0.000328>
15:11:21.908209 mprotect(0x7f6b006e3000, 4096, PROT_READ) = 0 <0.000353>
15:11:21.920594 munmap(0x7f6b006b6000, 9492) = 0 <0.000344>
15:11:21.931415 getuid()                = 0 <0.000342>
15:11:21.941044 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace/src/strace: Process 408 attached
 <unfinished ...>
[pid   408] 15:11:21.968455 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=5, tv_nsec=0},  <unfinished ...>
[pid   407] 15:11:21.981230 <... clone resumed>, child_tidptr=0x7f6b006b5850) = 408 <0.023196>
[pid   407] 15:11:21.993737 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=2, tv_nsec=0}, 0x7ffc6785eab0) = 0 <2.001052>
[pid   407] 15:11:24.020573 clock_settime(CLOCK_REALTIME, {tv_sec=1648048281, tv_nsec=940924397}) = 0 <0.000489>
[pid   407] 15:11:24.037254 wait4(-1,  <unfinished ...>
[pid   408] 15:11:26.979508 <... clock_nanosleep resumed>NULL) = 0 <5.001055>
[pid   408] 15:11:26.993907 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x4, 0x40), ...}) = 0 <0.000351>
[pid   408] 15:11:27.009070 ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0 <0.000358>
[pid   408] 15:11:27.024538 brk(NULL)   = 0x55a139c18000 <0.000325>
[pid   408] 15:11:27.036541 brk(0x55a139c39000) = 0x55a139c39000 <0.000467>
[pid   408] 15:11:27.050252 write(1, "diffnano: 5052758660, >= 3000000"..., 57diffnano: 5052758660, >= 3000000000: 1, <= 4000000000: 0
) = 57 <0.008914>
[pid   408] 15:11:27.076116 write(1, "Ended too late.  1648048286 >> 1"..., 42Ended too late.  1648048286 >> 1648048284
) = 42 <0.008892>
[pid   408] 15:11:27.102289 exit_group(0) = ?
[pid   408] 15:11:27.113111 +++ exited with 0 +++
15:11:27.122523 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 408 <3.080075>
15:11:27.137969 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=408, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
15:11:27.159424 clock_settime(CLOCK_REALTIME, {tv_sec=1648048289, tv_nsec=159303363}) = 0 <0.000448>
15:11:27.179822 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x4, 0x40), ...}) = 0 <0.000285>
15:11:27.195352 ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0 <0.000294>
15:11:27.207112 brk(NULL)               = 0x55a139c18000 <0.000271>
15:11:27.217462 brk(0x55a139c39000)     = 0x55a139c39000 <0.000295>
15:11:27.228071 write(1, "Test FAILED\n", 12Test FAILED
) = 12 <0.002106>
15:11:27.240042 exit_group(1)           = ?
15:11:27.248075 +++ exited with 1 +++

[metan-ucw]

I do not think that this is a significant, that probably just means that the order in which child/parent code is executed is different (the order of parent/child process execution is not guaranteed at all), but in the end they should synchronize just fine due to to the sleep calls, or at least it should be extremly unlikely that the order would end up being wrong. I do not think that there is anything wrong in the strace.

However I got an idea what we can try, looking at the strace I did realize that the clock_gettime() calls are VDSO. I wonder if forcing it to be a syscall (with the syscall() libc wrapper) would fix the issue.

[ZhangYet]

I simply replace if (clock_gettime(CLOCK_REALTIME, &tsend) != 0) with if (syscall(SYS_clock_gettime, CLOCK_REALTIME, &tsend) != 0), it did use system call now. But the test was still failed.

I doubt that clock_settime didn't update tk_core.timekeeper in this situation. Do you have any way to observe it?

16:05:39.640435 execve("./clock_settime_8-1.run-test", ["./clock_settime_8-1.run-test"], 0x7ffeba89d8c8 /* 12 vars */) = 0 <0.007427>
16:05:39.657894 brk(NULL)               = 0x55ac9eb1c000 <0.000211>
16:05:39.662934 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000239>
16:05:39.670285 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000249>
16:05:39.677680 fstat(3, {st_mode=S_IFREG|0644, st_size=9492, ...}) = 0 <0.000301>
16:05:39.696335 mmap(NULL, 9492, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc16ce01000 <0.000472>
16:05:39.697551 close(3)                = 0 <0.000326>
16:05:39.698199 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000282>
16:05:39.702253 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@n\2\0\0\0\0\0"..., 832) = 832 <0.000262>
16:05:39.707355 fstat(3, {st_mode=S_IFREG|0755, st_size=1839792, ...}) = 0 <0.000256>
16:05:39.710396 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc16cdff000 <0.000203>
16:05:39.714904 mmap(NULL, 1852680, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc16cc3a000 <0.000255>
16:05:39.721754 mprotect(0x7fc16cc5f000, 1662976, PROT_NONE) = 0 <0.000328>
16:05:39.731252 mmap(0x7fc16cc5f000, 1355776, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7fc16cc5f000 <0.001629>
16:05:39.734759 mmap(0x7fc16cdaa000, 303104, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x170000) = 0x7fc16cdaa000 <0.001545>
16:05:39.742005 mmap(0x7fc16cdf5000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ba000) = 0x7fc16cdf5000 <0.000233>
16:05:39.750771 mmap(0x7fc16cdfb000, 13576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fc16cdfb000 <0.002003>
16:05:39.756535 close(3)                = 0 <0.000252>
16:05:39.762214 arch_prctl(ARCH_SET_FS, 0x7fc16ce00580) = 0 <0.000240>
16:05:39.767517 mprotect(0x7fc16cdf5000, 12288, PROT_READ) = 0 <0.000228>
16:05:39.770840 mprotect(0x55ac9de3d000, 4096, PROT_READ) = 0 <0.000338>
16:05:39.776846 mprotect(0x7fc16ce2e000, 4096, PROT_READ) = 0 <0.000250>
16:05:39.783087 munmap(0x7fc16ce01000, 9492) = 0 <0.000271>
16:05:39.786685 getuid()                = 0 <0.000237>
16:05:39.790050 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fc16ce00850) = 242 <0.000975>
16:05:39.811582 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=2, tv_nsec=0}, strace/src/strace: Process 242 attached
 <unfinished ...>
[pid   242] 16:05:39.925571 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=5, tv_nsec=0},  <unfinished ...>
[pid   241] 16:05:41.814445 <... clock_nanosleep resumed>0x7ffea60554d0) = 0 <2.001298>
[pid   241] 16:05:41.815036 clock_settime(CLOCK_REALTIME, {tv_sec=1648137939, tv_nsec=789588584}) = 0 <0.001216>
[pid   241] 16:05:39.791952 wait4(-1,  <unfinished ...>
[pid   242] 16:05:44.940559 <... clock_nanosleep resumed>NULL) = 0 <5.017063>
[pid   242] 16:05:44.973514 clock_gettime(CLOCK_REALTIME, {tv_sec=1648137944, tv_nsec=983608720}) = 0 <0.010095>
[pid   242] 16:05:44.992051 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x4, 0x40), ...}) = 0 <0.004613>
[pid   242] 16:05:45.005379 ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0 <0.005385>
[pid   242] 16:05:45.019139 brk(NULL)   = 0x55ac9eb1c000 <0.004506>
[pid   242] 16:05:45.028473 brk(0x55ac9eb3d000) = 0x55ac9eb3d000 <0.005420>
[pid   242] 16:05:45.039010 write(1, "Ended too late.  1648137944 >> 1"..., 42Ended too late.  1648137944 >> 1648137942
) = 42 <0.015870>
[pid   242] 16:05:45.059297 exit_group(0) = ?
[pid   242] 16:05:45.066942 +++ exited with 0 +++
16:05:45.067410 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 242 <3.244936>
16:05:45.074690 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=242, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
16:05:45.080484 clock_settime(CLOCK_REALTIME, {tv_sec=1648137947, tv_nsec=80418563}) = 0 <0.000311>
16:05:47.090123 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x4, 0x40), ...}) = 0 <0.000014>
16:05:47.092459 ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0 <0.000043>
16:05:47.096544 brk(NULL)               = 0x55ac9eb1c000 <0.000029>
16:05:47.101391 brk(0x55ac9eb3d000)     = 0x55ac9eb3d000 <0.000032>
16:05:47.104324 write(1, "Test FAILED\n", 12Test FAILED
) = 12 <0.000029>
16:05:47.111110 exit_group(1)           = ?
16:05:47.114623 +++ exited with 1 +++

[ZhangYet]

@metan-ucw I tried to add some modules which the host machine loaded into the VM. But still failed. Do you have any new idea?

[ZhangYet]

I build a new rootfs with the 20200515 tag. And the case pass in lava now. So I close this issue.