Python / OpenCV 应用程序锁定问题答案

【问题标题】：Python / OpenCV application lockup issuePython / OpenCV 应用程序锁定问题
【发布时间】：2015-05-14 22:09:25
【问题描述】：

我在 64 核 Linux 机器上运行的 Python 应用程序通常可以正常运行。然后经过一段随机的时间（通常大约 0.5 到 1.5 天）后，我突然开始频繁出现超过 10 秒的暂停/锁定！在这些锁定期间，系统 CPU 时间（即内核中的时间）可能超过 90%（是的：所有 64 个内核的 90%，而不仅仅是一个 CPU）。

我的应用程序在一天中经常重启。重新启动应用程序并不能解决问题。但是，重启机器就可以了。

问题 1：什么会导致 90% 的系统 CPU 时间持续 10 秒？所有系统 CPU 时间都在我的父 Python 进程中，而不是在通过 Python 的多处理或其他进程创建的子进程中。所以这意味着大约 60 多个线程在内核中花费 10 多秒。我什至不确定这是 Python 问题还是 Linux 内核问题。

问题 2：重启能解决问题一定是找出原因的重要线索。在我的应用程序重新启动之间而不是在重新启动之间，系统上可能会耗尽哪些 Linux 资源，这可能会导致此问题卡住？

到目前为止我为解决这个问题所做的尝试/解决了这个问题

下面我会提到很多多处理。那是因为应用程序在一个循环中运行，而多处理仅在循环的一部分中使用。高 CPU 几乎总是在所有多处理调用完成后立即发生。我不确定这是对原因的暗示还是红鲱鱼。

我的应用程序运行一个线程，该线程使用psutil 每 0.5 秒注销一次进程和系统 CPU 统计信息。我已经通过top 独立确认了它所报告的内容。
我已将我的应用程序从 Python 2.7 转换为 Python 3.4，因为 Python 3.2 获得了新的 GIL 实现，而 3.4 重写了多处理。虽然这改进了一些事情，但它并没有解决问题（请参阅我要离开的my previous SO question，因为它仍然是一个有用的答案，如果不是总答案的话）。
我已更换操作系统。最初是 Ubuntu 12 LTS，现在是 CentOS 7。没有区别。
事实证明，Python/Linux 中的多线程和多处理会发生冲突，因此不建议同时使用，Python 3.4 现在有 forkserver 和 spawn 多处理上下文。我试过了，没什么区别。
我检查了 /dev/shm 以查看我是否用完了共享内存（Python 3.4 使用它来管理多处理），没有
lsof 输出列出所有资源 here
很难在其他机器上进行测试，因为我运行了一个由 59 个子进程组成的多进程池，而且我周围没有任何其他 64 核机器
我无法使用线程而不是进程来运行它，因为 GIL 导致它运行速度不够快（这就是为什么我首先切换到多处理）
我曾尝试在一个运行缓慢的线程上使用strace（它不能跨所有线程运行，因为它会使应用程序减慢太多）。下面是我得到的，并没有告诉我太多。
ltrace 不起作用，因为您不能在线程 ID 上使用 -p。即使只是在主线程（没有-f）上运行它也会使应用程序如此缓慢以至于问题没有出现。
问题与负载无关。它有时会在满载时运行良好，然后在半载时，它会突然出现这个问题。
即使我每晚重新启动机器，问题每隔几天就会出现一次。

环境/注意事项：

从源代码编译的 Python 3.4.3
CentOS 7 完全最新。 uname -a: Linux 3.10.0-229.4.2.el7.x86_64 #1 SMP Wed May 13 10:06:09 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux（尽管此内核更新仅在今天应用）
机器有 128GB 内存并且有足够的空闲空间
我使用链接到 ATLAS 的 numpy。我知道 OpenBLAS 与 Python 多处理发生冲突，但 ATLAS 没有，并且我尝试过的 Python 3.4 的 forkserver 和 spawn 解决了这种冲突。
我使用 OpenCV，它也做很多并行工作
我使用ctypes 访问相机制造商提供的C .so 库
应用程序以 root 身份运行（我链接到的 C 库的要求）
Python 多处理 Pool 在由 if __name__ == "__main__": 保护的代码和主线程中创建

更新 strace 结果

有几次我设法 strace 以 100% 的“系统”CPU 运行的线程。但只有一次，我从中得到了任何有意义的东西。请参阅下面的 10:24:12.446614 通话，需要 1.4 秒。鉴于它与您在大多数其他调用中看到的 ID (0x7f05e4d1072c) 相同，我猜这是 Python 的 GIL 同步。这个猜测有意义吗？如果是这样，那么问题是为什么等待需要 1.4 秒？有人不发布 GIL 吗？

10:24:12.375456 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.000823>
10:24:12.377076 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.002419>
10:24:12.379588 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.001898>
10:24:12.382324 sched_yield()           = 0 <0.000186>
10:24:12.382596 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.004023>
10:24:12.387029 sched_yield()           = 0 <0.000175>
10:24:12.387279 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.054431>
10:24:12.442018 sched_yield()           = 0 <0.000050>
10:24:12.442157 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.003902>
10:24:12.446168 futex(0x7f05e4d1022c, FUTEX_WAKE, 1) = 1 <0.000052>
10:24:12.446316 futex(0x7f05e4d11cac, FUTEX_WAKE, 1) = 1 <0.000056>
10:24:12.446614 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <1.439739>
10:24:13.886513 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.002381>
10:24:13.889079 sched_yield()           = 0 <0.000016>
10:24:13.889135 sched_yield()           = 0 <0.000049>
10:24:13.889244 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.032761>
10:24:13.922147 sched_yield()           = 0 <0.000020>
10:24:13.922285 sched_yield()           = 0 <0.000104>
10:24:13.923628 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.002320>
10:24:13.926090 sched_yield()           = 0 <0.000018>
10:24:13.926244 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.000265>
10:24:13.926667 sched_yield()           = 0 <0.000027>
10:24:13.926775 sched_yield()           = 0 <0.000042>
10:24:13.926964 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000117>
10:24:13.927241 futex(0x7f05e4d110ac, FUTEX_WAKE, 1) = 1 <0.000099>
10:24:13.927455 futex(0x7f05e4d11d2c, FUTEX_WAKE, 1) = 1 <0.000186>
10:24:13.931318 futex(0x7f05e4d1072c, FUTEX_WAIT, 2, NULL) = 0 <0.000678>

【问题讨论】：

使用ipcs -us 我发现信号量数组用完了。提高限制只会让我有更多的时间，直到我再次用尽阵列。起初我认为信号量与 Python 多处理相关，但结果只是通过ctypes.CDLL(...) 链接到相机.so（上面提到过）必须导致相机驱动程序分配一个信号量数组。这种链接发生在每个子进程中，因此分配了很多。我目前正在调查这是否是问题的原因。
虽然信号量用完是个问题，但这不是答案。我有一个测试套件，当连续运行时会显示高 CPU 问题。测试套件在未链接到相机驱动程序并且有可用的信号量数组时仍然显示问题。
你能检查你的内核是否有修复这个错误的方法吗？ groups.google.com/forum/#!topic/mechanical-sympathy/QbmpZxp6C64
感谢@linuxfan。我肯定在使用受此错误影响的 CentOS 版本，它听起来在正确的区域，但讨论表明症状应该是低 CPU（线程在不应该等待时等待）而不是我看到的 100% CPU。所以我不确定是不是这样。我很想尝试修复，但 CentOS 还没有提供修复，而且我以前从未从头开始编译过 Linux 内核。
既然这么大，这里是 lsof 的输出：pastebin.com/1nebcamY

标签： python multithreading opencv multiprocessing

【解决方案1】：

我已经设法从gdb 获得线程转储，此时有 40 多个线程显示 100% 的“系统”CPU 时间。

这是每个线程都相同的回溯：

#0  0x00007fffebe9b407 in cv::ThresholdRunner::operator()(cv::Range const&) const () from /usr/local/lib/libopencv_imgproc.so.3.0
#1  0x00007fffecfe44a0 in tbb::interface6::internal::start_for<tbb::blocked_range<int>, (anonymous namespace)::ProxyLoopBody, tbb::auto_partitioner const>::execute() () from /usr/local/lib/libopencv_core.so.3.0
#2  0x00007fffe967496a in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::local_wait_for_all(tbb::task&, tbb::task*) () from /lib64/libtbb.so.2
#3  0x00007fffe96705a6 in tbb::internal::arena::process(tbb::internal::generic_scheduler&) () from /lib64/libtbb.so.2
#4  0x00007fffe966fc6b in tbb::internal::market::process(rml::job&) () from /lib64/libtbb.so.2
#5  0x00007fffe966d65f in tbb::internal::rml::private_worker::run() () from /lib64/libtbb.so.2
#6  0x00007fffe966d859 in tbb::internal::rml::private_worker::thread_routine(void*) () from /lib64/libtbb.so.2
#7  0x00007ffff76e9df5 in start_thread () from /lib64/libpthread.so.0
#8  0x00007ffff6d0e1ad in clone () from /lib64/libc.so.6

我最初的问题将 Python 和 Linux 放在首位，但问题似乎在于 TBB 和/或 OpenCV。由于带有 TBB 的 OpenCV 被如此广泛地使用，我认为它还必须以某种方式涉及与我的特定环境的相互作用。也许是因为它是 64 核机器？

我在关闭 TBB 的情况下重新编译了 OpenCV，到目前为止问题还没有再次出现。但我的应用现在运行速度较慢。

我有 posted this as a bug to OpenCV 并将使用来自该答案的任何内容更新此答案。

【讨论】：