1

我正在尝试对在 EC2 上的 Ubuntu 11.04 上的 tornado 2.4 上运行的应用程序进行故障排除。它似乎定期达到 100% CPU 并在该请求下停止几秒钟。

非常感谢您对此的任何帮助。

症状：

  • top 在停止时显示 100% cpu。通常服务器的 CPU 利用率约为 30-60%。
  • 它每 2-5 分钟停止一次请求。我已经检查过没有影响这一点的 cronjobs。
  • 它会停止大约 2 到 9 秒。问题在重新启动龙卷风时消失，并随着龙卷风正常运行时间而恶化。服务器启动的时间越长，它停止的时间就越长。
  • 出现问题的 Http 请求似乎没有任何模式。
  • 有趣的是，日志中的下一个请求有时有时与停止持续时间匹配，有时则不匹配。例子：
00:00:00      GET /some/request ()
00:00:09      GET /next/request (9000ms)

00:00:00     GET /some/request ()
00:00:09     GET /next/request (1ms)
# 9 seconds gap in requests is certainly not possible as clients are constantly polling.
  • 数据库（mongodb）显示没有昂贵或大量的查询。没有页面错误。数据库在同一台机器上 - 本地磁盘。
  • 与前几分钟相比，vmstat 显示读/写大小没有变化。

  • 龙卷风在 nginx 后面运行。

  • 在最有可能停止时发送 SIGINT，每次都会给出不同的堆栈跟踪。其中一些如下：

Traceback (most recent call last):
  File "chat/main.py", line 3396, in <module>
    main()
  File "chat/main.py", line 3392, in main
    tornado.ioloop.IOLoop.instance().start()
  File "/home/ubuntu/tornado/tornado/ioloop.py", line 515, in start
    self._run_callback(callback)
  File "/home/ubuntu/tornado/tornado/ioloop.py", line 370, in _run_callback
    callback()
  File "/home/ubuntu/tornado/tornado/stack_context.py", line 216, in wrapped
    callback(*args, **kwargs)
  File "/home/ubuntu/tornado/tornado/iostream.py", line 303, in wrapper
    callback(*args)
  File "/home/ubuntu/tornado/tornado/stack_context.py", line 216, in wrapped
    callback(*args, **kwargs)
  File "/home/ubuntu/tornado/tornado/httpserver.py", line 298, in _on_request_body
    self.request_callback(self._request)
  File "/home/ubuntu/tornado/tornado/web.py", line 1421, in __call__
    handler = spec.handler_class(self, request, **spec.kwargs)
  File "/home/ubuntu/tornado/tornado/web.py", line 126, in __init__
    application.ui_modules.iteritems())
  File "/home/ubuntu/tornado/tornado/web.py", line 125, in <genexpr>
    self.ui["_modules"] = ObjectDict((n, self._ui_module(n, m)) for n, m in
  File "/home/ubuntu/tornado/tornado/web.py", line 1114, in _ui_module
    def _ui_module(self, name, module):
KeyboardInterrupt

Traceback (most recent call last):
  File "chat/main.py", line 3398, in <module>
    main()
  File "chat/main.py", line 3394, in main
    tornado.ioloop.IOLoop.instance().start()
  File "/home/ubuntu/tornado/tornado/ioloop.py", line 515, in start
    self._run_callback(callback)
  File "/home/ubuntu/tornado/tornado/ioloop.py", line 370, in _run_callback
    callback()
  File "/home/ubuntu/tornado/tornado/stack_context.py", line 216, in wrapped
    callback(*args, **kwargs)
  File "/home/ubuntu/tornado/tornado/iostream.py", line 303, in wrapper
    callback(*args)
  File "/home/ubuntu/tornado/tornado/stack_context.py", line 216, in wrapped
    callback(*args, **kwargs)
  File "/home/ubuntu/tornado/tornado/httpserver.py", line 285, in _on_headers
    self.request_callback(self._request)
  File "/home/ubuntu/tornado/tornado/web.py", line 1408, in __call__
    transforms = [t(request) for t in self.transforms]
  File "/home/ubuntu/tornado/tornado/web.py", line 1811, in __init__
    def __init__(self, request):
KeyboardInterrupt

Traceback (most recent call last):
  File "chat/main.py", line 3351, in <module>
    main()
  File "chat/main.py", line 3347, in main
    tornado.ioloop.IOLoop.instance().start()
  File "/home/ubuntu/tornado/tornado/ioloop.py", line 571, in start
    self._handlers[fd](fd, events)
  File "/home/ubuntu/tornado/tornado/stack_context.py", line 216, in wrapped
    callback(*args, **kwargs)
  File "/home/ubuntu/tornado/tornado/netutil.py", line 342, in accept_handler
    callback(connection, address)
  File "/home/ubuntu/tornado/tornado/netutil.py", line 237, in _handle_connection
    self.handle_stream(stream, address)
  File "/home/ubuntu/tornado/tornado/httpserver.py", line 156, in handle_stream
    self.no_keep_alive, self.xheaders, self.protocol)
  File "/home/ubuntu/tornado/tornado/httpserver.py", line 183, in __init__
    self.stream.read_until(b("\r\n\r\n"), self._header_callback)
  File "/home/ubuntu/tornado/tornado/iostream.py", line 139, in read_until
    self._try_inline_read()
  File "/home/ubuntu/tornado/tornado/iostream.py", line 385, in _try_inline_read
    if self._read_to_buffer() == 0:
  File "/home/ubuntu/tornado/tornado/iostream.py", line 401, in _read_to_buffer
    chunk = self.read_from_fd()
  File "/home/ubuntu/tornado/tornado/iostream.py", line 632, in read_from_fd
    chunk = self.socket.recv(self.read_chunk_size)
KeyboardInterrupt

非常感谢有关如何解决此问题的任何提示。

进一步的观察：

  • strace -p 在挂起期间显示空输出。

  • ltrace -p 在挂起期间仅显示大量 free() 调用： free(0x6fa70080) = free(0x1175f8060) = free(0x117a5c370) =

4

1 回答 1

3

听起来您正遭受垃圾收集 (GC) 风暴的困扰。您描述的行为是该诊断的典型行为，并且ltrace进一步支持了该假设。

在您的使用情况下正在执行的主/事件循环中分配和处置了许多对象......并且由此产生了对free()的周期性调用。

一种可能的方法是分析您的代码（或您所依赖的库），看看您是否可以重构它以使用（和重用）来自预分配池的对象。

另一种可能的缓解措施是让您自己更频繁地调用来触发垃圾收集——总体上更昂贵，但每次调用的成本可能更低。（这将是一个更可预测的吞吐量的权衡）。

您也许可以使用Python: gc 模块来更深入地调查问题（使用gc.set_debug() ）和尝试简单的缓解措施（例如，在每次事务后调用gc.collect() ）。您也可以尝试使用gc.disable()运行您的应用程序一段合理的时间，以查看是否进一步涉及 Python 垃圾收集器。请注意，长时间禁用垃圾收集器几乎肯定会导致分页/交换……所以仅将其用于验证我们的假设，不要指望以任何有意义的方式解决问题。它可能只是将问题推迟到整个系统崩溃并需要重新启动。

这是在 Tornado 上的另一个 SO 线程中使用gc.collect()的示例： SO: Tornado memory leak on dropped connections

于 2013-02-28T21:52:26.217 回答