libpmemobj-cpp
libpmemobj-cpp copied to clipboard
pmem
test: obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/static-debug/helgrind)
Found on 9316fc7eaadfc9a7a4a9527116c75c0db135d8db
==28580== Helgrind, a thread error detector
==28580== Copyright (C) 2007-2015, and GNU GPL'd, by OpenWorks LLP et al.
==28580== Using Valgrind-3.12.0 and LibVEX; rerun with -h for copyright info
==28580== Command: ./obj_cpp_cond_var_posix.static-nondebug /dev/shm/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/test_obj_cpp_cond_var_posix1😘⠝⠧⠍⠇ɗPMDKӜ⥺🙋/testfile1
==28580== Parent PID: 28542
==28580==
==28580==
==28580== For counts of detected and suppressed errors, rerun with: -v
==28580== Use --history-level=approx or =none to gain increased speed, at
==28580== the cost of reduced accuracy of conflicting-access information
==28580== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 24460 from 29)
k my bad :) I had KEEP_GOING flag enabled and passing test overwrote failing test log. Here is correct one:
==2703== Helgrind, a thread error detector
==2703== Copyright (C) 2007-2015, and GNU GPL'd, by OpenWorks LLP et al.
==2703== Using Valgrind-3.12.0 and LibVEX; rerun with -h for copyright info
==2703== Command: ./obj_cpp_cond_var_posix.static-debug /dev/shm/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/LoremipsumdolorsitametconsecteturadipiscingelitVivamuslacinianibhattortordictumsollicitudinNullamvariusvestibulumligulaetegestaselitsemperidMaurisultriciesligulaeuipsumtinciduntluctusMorbimaximusvariusdolorid/test_obj_cpp_cond_var_posix1😘⠝⠧⠍⠇ɗPMDKӜ⥺🙋/testfile1
==2703== Parent PID: 2667
==2703==
==2703== ---Thread-Announcement------------------------------------------
==2703==
==2703== Thread #1218 was created
==2703== at 0x68A6E5E: clone (in /usr/lib64/libc-2.26.so)
==2703== by 0x6575D72: pthread_create@@GLIBC_2.2.5 (in /usr/lib64/libpthread-2.26.so)
==2703== by 0x4C367AD: pthread_create_WRK (hg_intercepts.c:427)
==2703== by 0x4C3789F: pthread_create@* (hg_intercepts.c:460)
==2703== by 0x4F124F: os_thread_create (os_thread_posix.c:353)
==2703== by 0x4F01EB: ut_thread_create (ut_pthread.c:48)
==2703== by 0x409BED: void (anonymous namespace)::mutex_test<void* (*)(void*), void* (*)(void*)>(pmem::obj::pool<(anonymous namespace)::root>&, bool, bool, void* (*)(void*), void* (*)(void*)) (obj_cpp_cond_var_posix.cpp:448)
==2703== by 0x405549: main (obj_cpp_cond_var_posix.cpp:487)
==2703==
==2703== ----------------------------------------------------------------
==2703==
==2703== Thread #1218: pthread_cond_{signal,broadcast}: associated lock is not held by calling thread
==2703== at 0x4C344DC: pthread_cond_signal_WRK (hg_intercepts.c:1376)
==2703== by 0x4C37CCD: pthread_cond_signal@* (hg_intercepts.c:1397)
==2703== by 0x657C31C: pthread_cond_timedwait@@GLIBC_2.3.2 (in /usr/lib64/libpthread-2.26.so)
==2703== by 0x4C36E80: pthread_cond_timedwait_WRK (hg_intercepts.c:1287)
==2703== by 0x4C37CC2: pthread_cond_timedwait@* (hg_intercepts.c:1322)
==2703== by 0x4123CF: os_cond_timedwait (os_thread_posix.c:328)
==2703== by 0x449278: pmemobj_cond_timedwait (sync.c:613)
==2703== by 0x40B820: std::__1::cv_status pmem::obj::condition_variable::wait_until_impl<std::__1::chrono::system_clock, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000l> > >(pmem::obj::mutex&, std::__1::chrono::time_point<std::__1::chrono::system_clock, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000l> > > const&) (condition_variable.hpp:544)
==2703== by 0x40C359: std::__1::cv_status pmem::obj::condition_variable::wait_for<std::__1::unique_lock<pmem::obj::mutex>, long long, std::__1::ratio<1l, 1000l> >(std::__1::unique_lock<pmem::obj::mutex>&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> > const&) (condition_variable.hpp:377)
==2703== by 0x408E3A: (anonymous namespace)::reader_lock_for(void*) (obj_cpp_cond_var_posix.cpp:363)
==2703== by 0x4C369A1: mythread_wrapper (hg_intercepts.c:389)
==2703== by 0x6575608: start_thread (in /usr/lib64/libpthread-2.26.so)
==2703==
==2703== ---Thread-Announcement------------------------------------------
==2703==
==2703== Thread #1264 was created
==2703== at 0x68A6E5E: clone (in /usr/lib64/libc-2.26.so)
==2703== by 0x6575D72: pthread_create@@GLIBC_2.2.5 (in /usr/lib64/libpthread-2.26.so)
==2703== by 0x4C367AD: pthread_create_WRK (hg_intercepts.c:427)
==2703== by 0x4C3789F: pthread_create@* (hg_intercepts.c:460)
==2703== by 0x4F124F: os_thread_create (os_thread_posix.c:353)
==2703== by 0x4F01EB: ut_thread_create (ut_pthread.c:48)
==2703== by 0x409BED: void (anonymous namespace)::mutex_test<void* (*)(void*), void* (*)(void*)>(pmem::obj::pool<(anonymous namespace)::root>&, bool, bool, void* (*)(void*), void* (*)(void*)) (obj_cpp_cond_var_posix.cpp:448)
==2703== by 0x4055AB: main (obj_cpp_cond_var_posix.cpp:490)
==2703==
==2703== ----------------------------------------------------------------
==2703==
==2703== Thread #1264: pthread_cond_{signal,broadcast}: associated lock is not held by calling thread
==2703== at 0x4C344DC: pthread_cond_signal_WRK (hg_intercepts.c:1376)
==2703== by 0x4C37CCD: pthread_cond_signal@* (hg_intercepts.c:1397)
==2703== by 0x657C31C: pthread_cond_timedwait@@GLIBC_2.3.2 (in /usr/lib64/libpthread-2.26.so)
==2703== by 0x4C36E80: pthread_cond_timedwait_WRK (hg_intercepts.c:1287)
==2703== by 0x4C37CC2: pthread_cond_timedwait@* (hg_intercepts.c:1322)
==2703== by 0x4123CF: os_cond_timedwait (os_thread_posix.c:328)
==2703== by 0x449278: pmemobj_cond_timedwait (sync.c:613)
==2703== by 0x40B820: std::__1::cv_status pmem::obj::condition_variable::wait_until_impl<std::__1::chrono::system_clock, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000l> > >(pmem::obj::mutex&, std::__1::chrono::time_point<std::__1::chrono::system_clock, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000l> > > const&) (condition_variable.hpp:544)
==2703== by 0x40C359: std::__1::cv_status pmem::obj::condition_variable::wait_for<std::__1::unique_lock<pmem::obj::mutex>, long long, std::__1::ratio<1l, 1000l> >(std::__1::unique_lock<pmem::obj::mutex>&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> > const&) (condition_variable.hpp:377)
==2703== by 0x408E3A: (anonymous namespace)::reader_lock_for(void*) (obj_cpp_cond_var_posix.cpp:363)
==2703== by 0x4C369A1: mythread_wrapper (hg_intercepts.c:389)
==2703== by 0x6575608: start_thread (in /usr/lib64/libpthread-2.26.so)
==2703==
==2703==
==2703== For counts of detected and suppressed errors, rerun with: -v
==2703== Use --history-level=approx or =none to gain increased speed, at
==2703== the cost of reduced accuracy of conflicting-access information
==2703== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 1007335 from 79)
worksforme.
std::unique_lock<nvobj::mutex> lock((*proot)->pmutex);
auto ret = (*proot)->cond.wait_for(lock, wait_time);
This is the code that vg is complaining about in your log. This scenario literally can't happen unless std::unique_lock<> doesn't work.
Please, provide more info about test environment: OS version, glibc version, etc. Otherwise, we don't know how to reproduce it.
OS:
Linux Fedora27_10.91.38.54 4.15.3-300.fc27.x86_64
glibc:
GNU C Library (GNU libc) stable release version 2.26, by Roland McGrath et al. Copyright (C) 2017 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. Compiled by GNU CC version 7.2.1 20170915 (Red Hat 7.2.1-2). Available extensions: crypt add-on version 2.1 by Michael Glad and others GNU Libidn by Simon Josefsson Native POSIX Threads Library by Ulrich Drepper et al BIND-8.2.3-T5B libc ABIs: UNIQUE IFUNC For bug reporting instructions, please see: http://www.gnu.org/software/libc/bugs.html.
I believe it occurs only sometimes. It failed on our "long linux tests" group on Fedora (spec as described by Maciej above). I ran it again on the same machine and it failed only the second time. Now tested on 1.4-rc4-91-g32263d624
$ ./RUNTESTS obj_cpp_cond_var_posix/ -s TEST1 -t all
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/static-debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/static-nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/static-debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/static-nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
$
$ ./RUNTESTS obj_cpp_cond_var_posix/ -s TEST1 -t all
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/static-debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/pmem/static-nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/debug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/nondebug/helgrind)
obj_cpp_cond_var_posix/TEST1: PASS
obj_cpp_cond_var_posix/TEST1: SETUP (all/non-pmem/static-debug/helgrind)
obj_cpp_cond_var_posix/TEST1 failed with Valgrind. See helgrind1.log. First 20 lines below.
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583==
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== Thread #1028: pthread_cond_{signal,broadcast}: associated lock is not held by calling thread
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== at 0x4C344DC: pthread_cond_signal_WRK (hg_intercepts.c:1376)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x4C37CCD: pthread_cond_signal@* (hg_intercepts.c:1397)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x5B6039C: pthread_cond_timedwait@@GLIBC_2.3.2 (in /usr/lib64/libpthread-2.26.so)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x4C36E80: pthread_cond_timedwait_WRK (hg_intercepts.c:1287)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x4C37CC2: pthread_cond_timedwait@* (hg_intercepts.c:1322)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x40E9D9: os_cond_timedwait (os_thread_posix.c:328)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x441D07: pmemobj_cond_timedwait (sync.c:613)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x407EB1: std::cv_status pmem::obj::condition_variable::wait_until_impl<std::chrono::_V2::system_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >(pmem::obj::mutex&, std::chrono::time_point<std::chrono::_V2::system_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > const&) (condition_variable.hpp:544)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x407A2C: std::cv_status pmem::obj::condition_variable::wait_for<long, std::ratio<1l, 1000l> >(pmem::obj::mutex&, std::chrono::duration<long, std::ratio<1l, 1000l> > const&) (condition_variable.hpp:443)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x405344: (anonymous namespace)::reader_mutex_for(void*) (obj_cpp_cond_var_posix.cpp:303)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x4C369A1: mythread_wrapper (hg_intercepts.c:389)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== by 0x5B5961A: start_thread (in /usr/lib64/libpthread-2.26.so)
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583==
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583==
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== For counts of detected and suppressed errors, rerun with: -v
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== Use --history-level=approx or =none to gain increased speed, at
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== the cost of reduced accuracy of conflicting-access information
obj_cpp_cond_var_posix/TEST1 helgrind1.log ==26583== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1005439 from 70)
RUNTESTS: stopping: obj_cpp_cond_var_posix//TEST1 failed, TEST=all FS=non-pmem BUILD=static-debug
1 tests failed:
obj_cpp_cond_var_posix//TEST1
