While testing a 'pthread-rwlock' testdir on various VMs with 8 CPUs,
there was also a failure of 'test-pthread-cond' on Debian 10.
It's reproducible: On that Debian 10.7 VM (glibc 2.28, Linux 4.19.0)
with 8 CPUs, 'test-pthread-cond' with a probability of ca. 20%..30%
aborts. Stack trace:
test-pthread-cond.c:218
-> test-pthread-cond.c:186
'ltrace' and 'strace' can be used to get a log of the two threads
(attached):
$ ltrace -f -r llog05 ./test-pthread-cond
$ strace -f -r -ttt slog08 ./test-pthread-cond
The relevant lines in llog05:
2409 0.000040 nanosleep(0x7fff1f9ee690, 0x7fff1f9ee6e0, 0x7fff1f9ee6e0,
0x7ff543b6e917 <unfinished ...>
2411 0.000142 gettimeofday(0x7ff543a89ea0, 0) = 0
2411 0.000125 pthread_cond_timedwait(0x5647187a4140, 0x5647187a4180,
0x7ff543a89ed0, 0x20c49ba5e353f7cf <unfinished ...>
2409 2.034394 <... nanosleep resumed> ) = 0
2409 0.000087 pthread_mutex_lock(0x5647187a4180, 0x7fff1f9ee6e0, 0,
0x7ff543c60bf0) = 0
2409 0.000612 pthread_cond_signal(0x5647187a4140, 0, 0, 0) = 0
2409 0.000618 pthread_mutex_unlock(0x5647187a4180, 129, 1, 0x7ff543c5d5d6
<unfinished ...>
2411 0.000242 <... pthread_cond_timedwait resumed> ) = 0
2409 0.000026 <... pthread_mutex_unlock resumed> ) = 0
They show that while the main thread sleeps for more than 2 seconds, the
pthread_cond_timedwait invocation in the other thread, that has a timeout
of 1 second as argument
- takes more than 2 seconds to complete,
- when it completes, returns 0, not ETIMEDOUT.
Similarly, in the strace log. Here you can see the absolute time stamps:
2550 1719588804.808799 (+ 0.000024) nanosleep({tv_sec=2, tv_nsec=0},
<unfinished ...>
2552 1719588804.808810 (+ 0.000011) futex(0x562c763d816c,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1719588805,
tv_nsec=808799000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
2550 1719588806.863535 (+ 2.054725) <... nanosleep resumed>
0x7ffe334d1a90) = 0
2550 1719588806.863658 (+ 0.000122) futex(0x562c763d816c,
FUTEX_WAKE_PRIVATE, 1) = 1
Even though the futex was supposed to time out at 1719588805.808799
it terminated only at 1719588806.863658
which is more than 1 second too late.
It seems that this is the same bug as
<https://sourceware.org/bugzilla/show_bug.cgi?id=25847>.
Evidently, 'test-cond' (the test of the Gnulib condition variables) and
'test-cnd' (the test of the ISO C11 condition variables) fail as well,
occasionally, since they use pthread_cond_*.
2409 0.000000 signal(SIGALRM, 0) = 0
2409 0.000173 alarm(600) = 0
2409 0.000123 pthread_cond_init(0x5647187a4140, 0, 0, 0x7ff543b545c7) = 0
2409 0.000110 pthread_mutexattr_init(0x7fff1f9ee718, 0, 0, 0x7ff543b545c7) = 0
2409 0.000093 pthread_mutexattr_settype(0x7fff1f9ee718, 0, 0, 0x7ff543b545c7)
= 0
2409 0.000105 pthread_mutex_init(0x5647187a4180, 0x7fff1f9ee718, 0,
0x7ff543b545c7) = 0
2409 0.000122 pthread_mutexattr_destroy(0x7fff1f9ee718, 0x7fff1f9ee718, 640,
0) = 0
2409 0.000126 printf("Starting test_pthread_cond_wait "...) = 35
2409 0.000476 fflush(0x7ff543c4a760) = 0
2409 0.000995 pthread_create(0x7fff1f9ee6d8, 0, 0x5647187a1295, 0) = 0
2409 0.000474 sched_yield(0x3d0f00, 0, 0, 0 <unfinished ...>
2410 0.000208 pthread_mutex_lock(0x5647187a4180, 0, 0xb6bb9194910ce38a,
0x7ff543a8a700 <unfinished ...>
2409 0.000162 <... sched_yield resumed> ) = 0
2410 0.000030 <... pthread_mutex_lock resumed> ) = 0
2409 0.000017 nanosleep(0x7fff1f9ee690, 0x7fff1f9ee6e0, 0x7fff1f9ee6e0,
0x7ff543b6e917 <unfinished ...>
2410 0.000125 pthread_cond_wait(0x5647187a4140, 0x5647187a4180, 0, 0
<unfinished ...>
2409 2.040120 <... nanosleep resumed> ) = 0
2409 0.000090 pthread_mutex_lock(0x5647187a4180, 0x7fff1f9ee6e0, 0,
0x7ff543c60bf0) = 0
2409 0.000688 pthread_cond_signal(0x5647187a4140, 0, 0, 0) = 0
2409 0.000493 pthread_mutex_unlock(0x5647187a4180, 129, 1, 0x7ff543c5d5d6
<unfinished ...>
2410 0.000350 <... pthread_cond_wait resumed> ) = 0
2409 0.000040 <... pthread_mutex_unlock resumed> ) = 0
2410 0.000040 pthread_mutex_unlock(0x5647187a4180, 128, 0, 0 <unfinished ...>
2409 0.000247 pthread_join(0x7ff543a8a700, 0, 0x5647187a4180, 0x7ff543c6033a
<unfinished ...>
2410 0.000327 <... pthread_mutex_unlock resumed> ) = 0
2410 0.000296 +++ exited (status 0) +++
2409 0.000039 <... pthread_join resumed> ) = 0
2409 0.000089 puts(" OK") = 4
2409 0.000389 fflush(0x7ff543c4a760) = 0
2409 0.000270 printf("Starting test_pthread_cond_timed"...) = 40
2409 0.000394 fflush(0x7ff543c4a760) = 0
2409 0.000360 pthread_create(0x7fff1f9ee6d8, 0, 0x5647187a1669, 0) = 0
2409 0.000509 sched_yield(0x3d0f00, 0, 0, 0x7ff543a8a700 <unfinished ...>
2411 0.000267 pthread_mutex_lock(0x5647187a4180, 0, 0xb6bb9194910ce38a,
0x7ff543a8a700 <unfinished ...>
2409 0.000240 <... sched_yield resumed> ) = 0
2411 0.000036 <... pthread_mutex_lock resumed> ) = 0
2409 0.000040 nanosleep(0x7fff1f9ee690, 0x7fff1f9ee6e0, 0x7fff1f9ee6e0,
0x7ff543b6e917 <unfinished ...>
2411 0.000142 gettimeofday(0x7ff543a89ea0, 0) = 0
2411 0.000125 pthread_cond_timedwait(0x5647187a4140, 0x5647187a4180,
0x7ff543a89ed0, 0x20c49ba5e353f7cf <unfinished ...>
2409 2.034394 <... nanosleep resumed> ) = 0
2409 0.000087 pthread_mutex_lock(0x5647187a4180, 0x7fff1f9ee6e0, 0,
0x7ff543c60bf0) = 0
2409 0.000612 pthread_cond_signal(0x5647187a4140, 0, 0, 0) = 0
2409 0.000618 pthread_mutex_unlock(0x5647187a4180, 129, 1, 0x7ff543c5d5d6
<unfinished ...>
2411 0.000242 <... pthread_cond_timedwait resumed> ) = 0
2409 0.000026 <... pthread_mutex_unlock resumed> ) = 0
2411 0.000015 pthread_mutex_unlock(0x5647187a4180, 128, 0, 0 <unfinished ...>
2409 0.000149 pthread_join(0x7ff543a8a700, 0, 0x5647187a4180, 0x7ff543c6033a
<unfinished ...>
2411 0.000225 <... pthread_mutex_unlock resumed> ) = 0
2411 0.000231 +++ exited (status 0) +++
2409 0.000062 <... pthread_join resumed> ) = 0
2409 0.000054 abort( <no return ...>
2409 0.000530 --- SIGABRT (Aborted) ---
2409 0.000165 +++ killed by SIGABRT +++
2550 1719588801.125332 (+ 0.000000) execve("./test-pthread-cond",
["./test-pthread-cond"], 0x7ffecbb780d8 /* 39 vars */) = 0
2550 1719588801.125557 (+ 0.000224) brk(NULL) = 0x562c77894000
2550 1719588801.125614 (+ 0.000056) access("/etc/ld.so.preload", R_OK) =
-1 ENOENT (No such file or directory)
2550 1719588801.125712 (+ 0.000098) openat(AT_FDCWD, "/etc/ld.so.cache",
O_RDONLY|O_CLOEXEC) = 3
2550 1719588801.125764 (+ 0.000051) fstat(3, {st_mode=S_IFREG|0644,
st_size=94441, ...}) = 0
2550 1719588801.125806 (+ 0.000042) mmap(NULL, 94441, PROT_READ,
MAP_PRIVATE, 3, 0) = 0x7fa730f47000
2550 1719588801.125847 (+ 0.000041) close(3) = 0
2550 1719588801.125888 (+ 0.000040) openat(AT_FDCWD,
"/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
2550 1719588801.125935 (+ 0.000047) read(3,
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@l\0\0\0\0\0\0"..., 832) = 832
2550 1719588801.125977 (+ 0.000041) fstat(3, {st_mode=S_IFREG|0755,
st_size=146968, ...}) = 0
2550 1719588801.126016 (+ 0.000039) mmap(NULL, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa730f45000
2550 1719588801.126058 (+ 0.000042) mmap(NULL, 132288, PROT_READ,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa730f24000
2550 1719588801.126100 (+ 0.000041) mmap(0x7fa730f2a000, 61440,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) =
0x7fa730f2a000
2550 1719588801.126144 (+ 0.000044) mmap(0x7fa730f39000, 24576, PROT_READ,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x7fa730f39000
2550 1719588801.126185 (+ 0.000040) mmap(0x7fa730f3f000, 8192,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a000) =
0x7fa730f3f000
2550 1719588801.126229 (+ 0.000044) mmap(0x7fa730f41000, 13504,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fa730f41000
2550 1719588801.126275 (+ 0.000045) close(3) = 0
2550 1719588801.126317 (+ 0.000042) openat(AT_FDCWD,
"/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
2550 1719588801.126362 (+ 0.000044) read(3,
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260A\2\0\0\0\0\0"..., 832) = 832
2550 1719588801.126403 (+ 0.000041) fstat(3, {st_mode=S_IFREG|0755,
st_size=1824496, ...}) = 0
2550 1719588801.126444 (+ 0.000040) mmap(NULL, 1837056, PROT_READ,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa730d63000
2550 1719588801.126485 (+ 0.000040) mprotect(0x7fa730d85000, 1658880,
PROT_NONE) = 0
2550 1719588801.126531 (+ 0.000046) mmap(0x7fa730d85000, 1343488,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) =
0x7fa730d85000
2550 1719588801.126572 (+ 0.000041) mmap(0x7fa730ecd000, 311296,
PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16a000) = 0x7fa730ecd000
2550 1719588801.126621 (+ 0.000049) mmap(0x7fa730f1a000, 24576,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b6000) =
0x7fa730f1a000
2550 1719588801.126678 (+ 0.000056) mmap(0x7fa730f20000, 14336,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fa730f20000
2550 1719588801.126724 (+ 0.000046) close(3) = 0
2550 1719588801.126774 (+ 0.000049) mmap(NULL, 12288,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa730d60000
2550 1719588801.126818 (+ 0.000043) arch_prctl(ARCH_SET_FS,
0x7fa730d60740) = 0
2550 1719588801.126895 (+ 0.000077) mprotect(0x7fa730f1a000, 16384,
PROT_READ) = 0
2550 1719588801.126940 (+ 0.000045) mprotect(0x7fa730f3f000, 4096,
PROT_READ) = 0
2550 1719588801.127017 (+ 0.000077) mprotect(0x562c763d7000, 4096,
PROT_READ) = 0
2550 1719588801.127090 (+ 0.000072) mprotect(0x7fa730f86000, 4096,
PROT_READ) = 0
2550 1719588801.127147 (+ 0.000057) munmap(0x7fa730f47000, 94441) = 0
2550 1719588801.127205 (+ 0.000057) set_tid_address(0x7fa730d60a10) = 2550
2550 1719588801.127248 (+ 0.000043) set_robust_list(0x7fa730d60a20, 24) = 0
2550 1719588801.127294 (+ 0.000045) rt_sigaction(SIGRTMIN,
{sa_handler=0x7fa730f2a6b0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO,
sa_restorer=0x7fa730f36730}, NULL, 8) = 0
2550 1719588801.127352 (+ 0.000057) rt_sigaction(SIGRT_1,
{sa_handler=0x7fa730f2a740, sa_mask=[],
sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7fa730f36730}, NULL,
8) = 0
2550 1719588801.127398 (+ 0.000046) rt_sigprocmask(SIG_UNBLOCK, [RTMIN
RT_1], NULL, 8) = 0
2550 1719588801.127448 (+ 0.000049) prlimit64(0, RLIMIT_STACK, NULL,
{rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
2550 1719588801.127517 (+ 0.000069) rt_sigaction(SIGALRM,
{sa_handler=SIG_DFL, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART,
sa_restorer=0x7fa730d9a840}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
2550 1719588801.127574 (+ 0.000056) alarm(600) = 0
2550 1719588801.127634 (+ 0.000059) fstat(1, {st_mode=S_IFCHR|0620,
st_rdev=makedev(0x88, 0), ...}) = 0
2550 1719588801.127700 (+ 0.000066) brk(NULL) = 0x562c77894000
2550 1719588801.127743 (+ 0.000042) brk(0x562c778b5000) = 0x562c778b5000
2550 1719588801.127795 (+ 0.000052) write(1, "Starting
test_pthread_cond_wait "..., 35) = 35
2550 1719588801.127860 (+ 0.000065) mmap(NULL, 8392704, PROT_NONE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fa73055f000
2550 1719588801.127903 (+ 0.000043) mprotect(0x7fa730560000, 8388608,
PROT_READ|PROT_WRITE) = 0
2550 1719588801.127947 (+ 0.000043) clone(child_stack=0x7fa730d5efb0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0x7fa730d5f9d0, tls=0x7fa730d5f700, child_tidptr=0x7fa730d5f9d0)
= 2551
2551 1719588801.127997 (+ 0.000050) set_robust_list(0x7fa730d5f9e0, 24
<unfinished ...>
2550 1719588801.128008 (+ 0.000011) sched_yield( <unfinished ...>
2551 1719588801.128014 (+ 0.000005) <... set_robust_list resumed> ) = 0
2550 1719588801.128019 (+ 0.000005) <... sched_yield resumed> ) = 0
2550 1719588801.128036 (+ 0.000016) nanosleep({tv_sec=2, tv_nsec=0},
<unfinished ...>
2551 1719588801.128045 (+ 0.000008) futex(0x562c763d8168,
FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
2550 1719588804.807979 (+ 3.679934) <... nanosleep resumed>
0x7ffe334d1a90) = 0
2550 1719588804.808063 (+ 0.000084) futex(0x562c763d8168,
FUTEX_WAKE_PRIVATE, 1) = 1
2551 1719588804.808107 (+ 0.000043) <... futex resumed> ) = 0
2550 1719588804.808125 (+ 0.000017) futex(0x7fa730d5f9d0, FUTEX_WAIT,
2551, NULL <unfinished ...>
2551 1719588804.808132 (+ 0.000007) futex(0x562c763d8180,
FUTEX_WAKE_PRIVATE, 1) = 0
2551 1719588804.808228 (+ 0.000095) madvise(0x7fa73055f000, 8368128,
MADV_DONTNEED) = 0
2551 1719588804.808304 (+ 0.000076) exit(0) = ?
2551 1719588804.808384 (+ 0.000079) +++ exited with 0 +++
2550 1719588804.808390 (+ 0.000005) <... futex resumed> ) = 0
2550 1719588804.808429 (+ 0.000039) write(1, " OK\n", 4) = 4
2550 1719588804.808522 (+ 0.000092) write(1, "Starting
test_pthread_cond_timed"..., 40) = 40
2550 1719588804.808599 (+ 0.000077) clone(child_stack=0x7fa730d5efb0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0x7fa730d5f9d0, tls=0x7fa730d5f700, child_tidptr=0x7fa730d5f9d0)
= 2552
2550 1719588804.808736 (+ 0.000136) sched_yield( <unfinished ...>
2552 1719588804.808744 (+ 0.000007) set_robust_list(0x7fa730d5f9e0, 24
<unfinished ...>
2550 1719588804.808767 (+ 0.000023) <... sched_yield resumed> ) = 0
2552 1719588804.808774 (+ 0.000007) <... set_robust_list resumed> ) = 0
2550 1719588804.808799 (+ 0.000024) nanosleep({tv_sec=2, tv_nsec=0},
<unfinished ...>
2552 1719588804.808810 (+ 0.000011) futex(0x562c763d816c,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1719588805,
tv_nsec=808799000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
2550 1719588806.863535 (+ 2.054725) <... nanosleep resumed>
0x7ffe334d1a90) = 0
2550 1719588806.863658 (+ 0.000122) futex(0x562c763d816c,
FUTEX_WAKE_PRIVATE, 1) = 1
2550 1719588806.863963 (+ 0.000304) futex(0x7fa730d5f9d0, FUTEX_WAIT,
2552, NULL <unfinished ...>
2552 1719588806.863995 (+ 0.000032) <... futex resumed> ) = 0
2552 1719588806.864042 (+ 0.000046) futex(0x562c763d8180,
FUTEX_WAKE_PRIVATE, 1) = 0
2552 1719588806.864123 (+ 0.000080) madvise(0x7fa73055f000, 8368128,
MADV_DONTNEED) = 0
2552 1719588806.864207 (+ 0.000084) exit(0) = ?
2550 1719588806.864297 (+ 0.000089) <... futex resumed> ) = 0
2552 1719588806.864322 (+ 0.000025) +++ exited with 0 +++
2550 1719588806.864329 (+ 0.000006) rt_sigprocmask(SIG_UNBLOCK, [ABRT],
NULL, 8) = 0
2550 1719588806.864423 (+ 0.000094) rt_sigprocmask(SIG_BLOCK, ~[RTMIN
RT_1], [], 8) = 0
2550 1719588806.864509 (+ 0.000086) getpid() = 2550
2550 1719588806.864555 (+ 0.000045) gettid() = 2550
2550 1719588806.864602 (+ 0.000046) tgkill(2550, 2550, SIGABRT) = 0
2550 1719588806.864650 (+ 0.000048) rt_sigprocmask(SIG_SETMASK, [], NULL,
8) = 0
2550 1719588806.864705 (+ 0.000054) --- SIGABRT {si_signo=SIGABRT,
si_code=SI_TKILL, si_pid=2550, si_uid=1000} ---
2550 1719588806.864819 (+ 0.000114) +++ killed by SIGABRT +++
