Tim Jenness added a comment - 13/Aug/18 3:40 PM - edited Here's a trace from the debugger after the test had been hanging for a minute and the process was killed: * frame #0: 0x00007fff6043ca16 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007fff60605589 libsystem_pthread.dylib`_pthread_cond_wait + 732 frame #2: 0x000000010015ff01 python`take_gil + 417 frame #3: 0x0000000100160246 python`PyEval_AcquireThread + 22 frame #4: 0x0000000111944654 _cache.so`pybind11::gil_scoped_acquire::gil_scoped_acquire(this=0x00007ffeefbf8338) at pybind11.h:1773 frame #5: 0x0000000111944555 _cache.so`pybind11::gil_scoped_acquire::gil_scoped_acquire(this=0x00007ffeefbf8338) at pybind11.h:1748 frame #6: 0x00000001119881bf _cache.so`pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(this=0x000000010062dc38, args=0x00007ffeefbf87f8)::'lambda'(int const&)::operator()(int const&) const at functional.h:58 frame #7: 0x0000000111988184 _cache.so`std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > std::__1::__invoke_void_return_wrapper<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >::__call<pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&, int const&>(pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&&&, int const&&&) [inlined] decltype(__f=0x000000010062dc38, __args=0x00007ffeefbf87f8)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&>(fp)(std::__1::forward<int const&>(fp0))) std::__1::__invoke<pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&, int const&>(pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&&&, int const&&&) at type_traits:4428 frame #8: 0x0000000111988163 _cache.so`std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > std::__1::__invoke_void_return_wrapper<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >::__call<pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (__args=0x000000010062dc38, __args=0x00007ffeefbf87f8)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&, int const&>(pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)&&&, int const&&&) at __functional_base:318 frame #9: 0x0000000111987f90 _cache.so`std::__1::__function::__func<pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&), std::__1::allocator<pybind11::detail::type_caster<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, void>::load(pybind11::handle, bool)::'lambda'(int const&)>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>::operator(this=0x000000010062dc30, __arg=0x00007ffeefbf87f8)(int const&) at functional:1562 frame #10: 0x000000011198926e _cache.so`std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>::operator(this=0x000000010062dc30, __arg=0x00007ffeefbf87f8)(int const&) const at functional:1913 frame #11: 0x0000000111988ea8 _cache.so`std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >::operator(this=0x0000000100666110, key=0x00007ffeefbf87f8, func=0x000000010062dc30)<std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)> >(int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>) at Cache.h:263 frame #12: 0x0000000111988cf4 _cache.so`void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(this=0x0000000100667478, self=0x0000000100666110, key=0x00007ffeefbf87f8, func=<unavailable>)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)::operator()(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>) const at Cache.h:27 frame #13: 0x0000000111988c1b _cache.so`std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > pybind11::detail::argument_loader<lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (this=0x00007ffeefbf87e0, f=0x0000000100667478, (null)=std::__1::index_sequence<0UL, 1UL, 2UL> @ 0x00007ffeefbf8648, (null)=0x00007ffeefbf8700)> >::call_impl<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(pybind11::module&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)&, 0ul, 1ul, 2ul, pybind11::detail::void_type>(void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(pybind11::module&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)&&&, std::__1::integer_sequence<unsigned long, 0ul, 1ul, 2ul>, pybind11::detail::void_type&&) at cast.h:1870 frame #14: 0x0000000111983d38 _cache.so`std::__1::enable_if<!(std::is_void<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >::value), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >::type pybind11::detail::argument_loader<lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (this=0x00007ffeefbf87e0, f=0x0000000100667478)> >::call<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, pybind11::detail::void_type, void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(pybind11::module&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)&>(void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(pybind11::module&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)&&&) at cast.h:1847 frame #15: 0x0000000111983ade _cache.so`void pybind11::cpp_function::initialize<void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(pybind11::module&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, pybind11::name, pybind11::is_method, pybind11::sibling, pybind11::arg, pybind11::arg>(this=0x00000001119839a0, call=0x00007ffeefbf9168)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)&&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (*)(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>), pybind11::name const&, pybind11::is_method const&, pybind11::sibling const&, pybind11::arg const&, pybind11::arg const&)::'lambda'(pybind11::detail::function_call&)::operator()(pybind11::detail::function_call&) const at pybind11.h:155 frame #16: 0x00000001119839b8 _cache.so`void pybind11::cpp_function::initialize<void lsst::utils::python::declareCache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >(pybind11::module&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>, pybind11::name, pybind11::is_method, pybind11::sibling, pybind11::arg, pybind11::arg>(call=0x00007ffeefbf9168)::'lambda'(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>)&&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (*)(lsst::utils::Cache<int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, boost::hash<int>, std::__1::equal_to<int> >&, int const&, std::__1::function<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > (int const&)>), pybind11::name const&, pybind11::is_method const&, pybind11::sibling const&, pybind11::arg const&, pybind11::arg const&)::'lambda'(pybind11::detail::function_call&)::__invoke(pybind11::detail::function_call&) at pybind11.h:132 frame #17: 0x0000000111959649 _cache.so`pybind11::cpp_function::dispatcher(self=0x0000000109c6e7e0, args_in=0x00000001094d7dc8, kwargs_in=0x0000000000000000) at pybind11.h:627 frame #18: 0x000000010002dd78 python`_PyMethodDef_RawFastCallDict + 456 frame #19: 0x000000010002d4ef python`_PyObject_FastCallDict + 111 frame #20: 0x0000000100031782 python`method_call + 130 frame #21: 0x000000010002f1e2 python`PyObject_Call + 130 frame #22: 0x00000001000af638 python`slot_tp_call + 376 frame #23: 0x000000010002e573 python`_PyObject_FastCallKeywords + 179 frame #24: 0x000000010016f33f python`call_function + 399 frame #25: 0x000000010016cf99 python`_PyEval_EvalFrameDefault + 45705 frame #26: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #27: 0x000000010002ea73 python`_PyFunction_FastCallKeywords + 195 frame #28: 0x000000010016f265 python`call_function + 181 frame #29: 0x000000010016cf99 python`_PyEval_EvalFrameDefault + 45705 frame #30: 0x000000010002e368 python`function_code_fastcall + 120 frame #31: 0x000000010016f265 python`call_function + 181 frame #32: 0x000000010016cd19 python`_PyEval_EvalFrameDefault + 45065 frame #33: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #34: 0x000000010002ea73 python`_PyFunction_FastCallKeywords + 195 frame #35: 0x000000010016f265 python`call_function + 181 frame #36: 0x000000010016cf99 python`_PyEval_EvalFrameDefault + 45705 frame #37: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #38: 0x000000010002d867 python`_PyFunction_FastCallDict + 231 frame #39: 0x0000000100031782 python`method_call + 130 frame #40: 0x000000010002f1e2 python`PyObject_Call + 130 frame #41: 0x000000010016d1c6 python`_PyEval_EvalFrameDefault + 46262 frame #42: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #43: 0x000000010002d867 python`_PyFunction_FastCallDict + 231 frame #44: 0x00000001000af57d python`slot_tp_call + 189 frame #45: 0x000000010002e573 python`_PyObject_FastCallKeywords + 179 frame #46: 0x000000010016f33f python`call_function + 399 frame #47: 0x000000010016cf99 python`_PyEval_EvalFrameDefault + 45705 frame #48: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #49: 0x000000010002d867 python`_PyFunction_FastCallDict + 231 frame #50: 0x0000000100031782 python`method_call + 130 frame #51: 0x000000010002f1e2 python`PyObject_Call + 130 frame #52: 0x000000010016d1c6 python`_PyEval_EvalFrameDefault + 46262 frame #53: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #54: 0x000000010002d867 python`_PyFunction_FastCallDict + 231 frame #55: 0x00000001000af57d python`slot_tp_call + 189 frame #56: 0x000000010002e573 python`_PyObject_FastCallKeywords + 179 frame #57: 0x000000010016f33f python`call_function + 399 frame #58: 0x000000010016cf99 python`_PyEval_EvalFrameDefault + 45705 frame #59: 0x000000010002e368 python`function_code_fastcall + 120 frame #60: 0x000000010016f265 python`call_function + 181 frame #61: 0x000000010016cd19 python`_PyEval_EvalFrameDefault + 45065 frame #62: 0x000000010002e368 python`function_code_fastcall + 120 frame #63: 0x000000010016f265 python`call_function + 181 frame #64: 0x000000010016cd19 python`_PyEval_EvalFrameDefault + 45065 frame #65: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #66: 0x000000010002d867 python`_PyFunction_FastCallDict + 231 frame #67: 0x00000001000b1481 python`slot_tp_init + 193 frame #68: 0x00000001000bb441 python`type_call + 241 frame #69: 0x000000010002e573 python`_PyObject_FastCallKeywords + 179 frame #70: 0x000000010016f33f python`call_function + 399 frame #71: 0x000000010016cdaf python`_PyEval_EvalFrameDefault + 45215 frame #72: 0x0000000100160a42 python`_PyEval_EvalCodeWithName + 418 frame #73: 0x00000001001c49a0 python`PyRun_FileExFlags + 256 frame #74: 0x00000001001c4104 python`PyRun_SimpleFileExFlags + 388 frame #75: 0x00000001001efedc python`pymain_main + 9148 frame #76: 0x0000000100000ece python`main + 142 frame #77: 0x00007fff602ec015 libdyld.dylib`start + 1 frame #78: 0x00007fff602ec015 libdyld.dylib`start + 1

Tim Jenness added a comment - 13/Aug/18 4:40 PM Jim Bosch is it possible this is really a Python 3.7 and pybind11 interaction rather than a boost one? (unfortunately I can't build python3.7 with boost 1.66 because of a boost-python issue).

Jim Bosch added a comment - 13/Aug/18 6:12 PM Hard to rule out either, but Cache.h is pretty boost-heavy, so my money is on Boost.

Paul Price added a comment - 13/Aug/18 7:11 PM So the test is calling python from C++: pybind converts the python function into a std::function . It looks like that's trying to grab the GIL, when we never gave it up. I suspect a bug in pybind.

Paul Price added a comment - 13/Aug/18 7:52 PM The acquisition of the GIL was added in pybind 1.7. I think that's consistent with our history (pybind 1.6 --> pybind 2.2, right?).

Paul Price added a comment - 13/Aug/18 8:02 PM Tim Jenness , could you please try this: price@pap-laptop:~/LSST/utils (master=) $ git diff diff --git a/include/lsst/utils/python/Cache.h b/include/lsst/utils/python/Cache.h index f51fdd9..6127bcd 100644 --- a/include/lsst/utils/python/Cache.h +++ b/include/lsst/utils/python/Cache.h @@ -24,8 +24,9 @@ void declareCache(py::module & mod, std::string const& name) { cls.def(py::init<std::size_t>(), "maxElements"_a=0); cls.def("__call__", [](Class & self, Key const& key, std::function<Value(Key const& key)> func) { - return self(key, func); }, - "key"_a, "func"_a); + py::gil_scoped_release release; + return self(key, func); + }, "key"_a, "func"_a); cls.def("__getitem__", &Class::operator[]); cls.def("add", &Class::add, "key"_a, "value"_a); cls.def("size", &Class::size); The plan is to give up the GIL before pybind tries to get it back to call the function.

Tim Jenness added a comment - 13/Aug/18 9:37 PM All tests pass with this change. Does this mean it really is a bug in pybind11 or that I should apply this patch to utils?

Jim Bosch added a comment - 13/Aug/18 9:54 PM The recent pybind11 upgrade was from 2.1, not 1.7; I don't think we ever used anything earlier than 2.0. The logic of Paul Price 's fix seems sound to me, though I don't know what about pybind11 did actually change if it wasn't the commit found, or whether this would be considered a bug upstream. I assume the reason the callback is not being invoked by the thread in which it was defined is because pytest is creating multiple threads?  In any case, I think this is just good GIL citizenship, though I don't have a good sense for whether pybind11 could have made it unnecessary for us to handle it ourselves here.

Tim Jenness added a comment - 13/Aug/18 10:00 PM The test was hanging even if you run the test on its own with python (no pytest). I'll commit Paul Price 's fix and do a Jenkins run.

Tim Jenness added a comment - 15/Aug/18 11:01 AM The patch from Paul Price works on Jenkins and Python 3.7 so I think we should merge this. Jim Bosch can you please formally review?

Jim Bosch added a comment - 15/Aug/18 11:15 AM Looks good. I've created DM-15444 to try to record places where we've found a need to do GIL management that we don't completely understand; please link any other tickets that describe such workarounds to that ticket as well, so if (for example) pybind11 behavior changes again we have a record of all the places in the codebase we should revisit.