Python的time.sleep - 从不唤醒

Question

我觉得这个问题看起来简单，但让我很困惑。

[紧急消息：我猜对了。解决方案找到了。请查看答案。]

我正在使用Python的unittest框架来测试一个多线程的应用程序。这个过程很简单——我有大约5个工作线程在监控一个公共队列，还有一个生产者线程在为它们生成工作项。生产者线程是通过一个测试用例来触发的。

在这个测试中，队列里只放了一个任务。测试中的处理只是一个简单的占位符，真正的处理过程并没有执行，所以工作线程会休眠5秒钟，模拟任务完成前的等待时间，然后它就准备好去接另一个任务了。

这段代码是：

 logging.info("Sleep starting")
 time.sleep(5)
 logging.info("Waking up")

接下来是奇怪的部分。我看到了“开始休眠”的日志信息，但没有看到“醒来的”信息。程序卡住了，无法响应键盘中断（CTRL+C），而且CPU的负载非常低。

我在Windows和Ubuntu上都遇到了同样的问题（Python 2.6.2）。

我考虑过是否发生了异常并被隐藏了，所以我在第一行和第二行之间加了“print 1/0”——我看到了除以零的错误。然后我把它移到休眠之后，但我从未看到这个信息。

我想，“好吧，也许其他线程同时在尝试记录一些非常大的东西，而它还在缓冲中。它在干什么呢？”

这时，测试已经返回到unittest框架，它在等待线程开始工作，然后再测试系统的状态。

 logging.info("Test sleep starting")
 time.sleep(0.25)
 logging.info("Test waking up")

哇，这看起来很熟悉。它的卡住方式完全一样！第一个日志信息出现了，但第二个没有。

我最近对这个单元进行了大幅重写，所以我不能说“我什么都没动”，但我在我的修改中没有看到任何不对劲的地方。

可疑的地方：

• 我在使用Threading.Lock（因为我不知道如何处理GIL的安全性，所以我坚持我知道的。我觉得我的代码没有什么“死锁”的问题。

• 我对Python的unittest框架还很陌生。它是否做了什么重定向日志或类似的操作，可能会模拟这些症状？

• 不，我没有替换一个非标准的时间模块！

是什么导致线程无法醒来？我还遗漏了什么？

Answer 1

在Linux系统上，可以尝试将输入输出调度器更改为完全公平队列（CFQ）。

echo cfq > /sys/block/sda/queue/scheduler

Answer 2

唉。

工作线程 #1 正在休眠，过一会儿会醒来。醒来后，它会记录一个消息，但这时它被阻塞了。因为一次只能有一个线程在记录日志。

单元测试线程也在休眠，过一会儿会醒来。醒来后，它同样会记录一个消息，但也被阻塞了。一次只能有一个线程在记录日志。

还有一个之前没提到的工作线程 #2 正在安静地处理队列中的上一个项目，这时候第一个工作线程还在休眠。它处理到一个日志记录的地方。这个地方有一个参数是个对象，系统自动调用了 str() 函数。可是这个对象的 str() 函数有个bug；当它访问某些数据时会出现死锁。死锁发生在记录日志的过程中，这样就锁住了日志线程，让人觉得其他线程好像一直没醒过来。

除以零的测试没有影响，因为它的结果也是在尝试记录日志。