Possible memory leak

[ezdev128]

Hi,

I have memory leaks even in "hello, world" example listed here http://www.tornadoweb.org/en/stable/

Code of tornado_memory_test.py: http://pastebin.com/BfG7Na9Z

Here is an example of a problem:
$ python tornado_memory_test.py
No memory leaks found!
No memory leaks found!
[I 161031 18:00:54 web:1946] 200 GET /test (127.0.0.1) 0.87ms
Memory garbage detected
[gc stat]: 73 objects in garbage
Memory garbage detected
[gc stat]: 73 objects in garbage
Memory garbage detected
[gc stat]: 73 objects in garbage
[I 161031 18:01:11 web:1946] 200 GET /test (127.0.0.1) 0.73ms
Memory garbage detected
[gc stat]: 146 objects in garbage

Here is a verbose output of garbage: http://pastebin.com/BzXudRXd

$ pip freeze | grep -i tor
tornado==4.4.2

$ python -V
Python 2.7.12

Also tried on:
$ pip freeze | grep tor
tornado==4.5.dev1

$ python -V
Python 2.7.12

[zguangyu]

I also tested your script and get the following output.

$ python2 tornado_memory_leak_issue.py
No memory leaks found!
[I 161101 17:39:09 web:1971] 304 GET /test (127.0.0.1) 0.88ms
No memory leaks found!
No memory leaks found!
[I 161101 17:39:17 web:1971] 200 GET /test (127.0.0.1) 0.34ms
[W 161101 17:39:17 web:1971] 404 GET /favicon.ico (127.0.0.1) 0.52ms
No memory leaks found!

$ python2 -V
Python 2.7.12

$ pip2 show tornado
...
Version: 4.4.2

What's your operating system? I'm using a mac

[ezdev128]

I've tested on two machines:

1. Ubuntu 16.04.01 LTS
2. CentOS Linux release 7.2.1511 (Core)

[bdarnell]

I think if you run with gc.DEBUG_SAVEALL, then all objects involved in reference cycles end up in gc.garbage, so this doesn't indicate a leak. If you see a lot of objects here then it might improve performance to break up cycles manually. You could add gc.DEBUG_LEAK instead of gc.DEBUG_SAVEALL to get more information.

[ezdev128]

With gc.DEBUG_LEAK absolutely the same.
Here is full debug: http://pastebin.com/qrbLqwit

Memory increases rapidly

[bdarnell]

Yes, it's expected that memory increases rapidly with DEBUG_LEAK or DEBUG_SAVEALL - those options cause garbage objects to be saved even though they are collectable. It's not a real leak. Remove those options and the "leak" will go away.

There are a lot of traceback and frame objects in that log. It looks like something is holding on to an exception object which in turn holds on to a lot of other stuff. We may be able to reduce the overhead of garbage collection by breaking the cycle (although this isn't always possible).

[homm]

Hi, @bdarnell!

I also experiencing circular references problem on dummy handler. And this problem is related to connections. This is the debug script which searches for circular references in the garbage after request:

https://gist.github.com/homm/c20a7dc74f78d393f6ffac537532fd93

As the issue is related to connection, the server shouldn't be called from the browser because browser will keep connection for a while, and connection will keep references to resources associated with the last request. You should connect to the server from console:

$ curl http://localhost:8888/dummy/ && curl http://localhost:8888/collect/

connection will keep references to resources associated with the last request

By the way, I think this is also the issue: resources associated with the last request are not freed until connection is closed. Most likely there should be one solution.

My output for the script:

$ python --version
Python 2.7.6

$ python ./memtest.py 
GC disabled
Start on 8888
gc: collecting generation 2...
gc: objects in each generation: 508 0 10237
gc: collectable <tuple 0x7ff04eaec310>
gc: collectable <IOStream 0x7ff04b93a410>
gc: collectable <dict 0x7ff04b93db40>
gc: collectable <collections.deque 0x7ff04bb926e0>
gc: collectable <_HTTPRequestContext 0x7ff04b93a450>
gc: collectable <dict 0x7ff04b934a28>
gc: collectable <generator 0x7ff04b92a780>
gc: collectable <Runner 0x7ff04eb68d90>
gc: collectable <dict 0x7ff04b944d70>
gc: collectable <HTTP1Connection 0x7ff04b93a890>
gc: collectable <dict 0x7ff04b944a28>
gc: collectable <Future 0x7ff04b93a910>
gc: collectable <list 0x7ff04b9459e0>
gc: collectable <dict 0x7ff04b951398>
gc: collectable <_ServerRequestAdapter 0x7ff04b93a950>
gc: collectable <dict 0x7ff04b951e88>
gc: collectable <_RequestDispatcher 0x7ff04b93ac90>
gc: collectable <dict 0x7ff04bb97a28>
gc: collectable <list 0x7ff04b9457e8>
gc: collectable <list 0x7ff04b9457a0>
gc: collectable <Future 0x7ff04eb4f890>
gc: collectable <dict 0x7ff04b9444b0>
gc: collectable <frame 0xd8a980>
gc: collectable <generator 0x7ff04b92aeb0>
gc: collectable <Future 0x7ff04b93a810>
gc: collectable <dict 0x7ff04b9515c8>
gc: collectable <Future 0x7ff04b93a850>
gc: collectable <dict 0x7ff04b946050>
gc: collectable <Runner 0x7ff04b93a8d0>
gc: collectable <dict 0x7ff04b946910>
gc: collectable <cell 0x7ff04b94a600>
gc: collectable <tuple 0x7ff04ca00650>
gc: collectable <function 0x7ff04b942b90>
gc: collectable <cell 0x7ff04b94a718>
gc: collectable <cell 0x7ff04b94a750>
gc: collectable <list 0x7ff04b9313b0>
gc: collectable <tuple 0x7ff04b945290>
gc: collectable <function 0x7ff04b942c08>
gc: collectable <cell 0x7ff04b94a130>
gc: collectable <tuple 0x7ff04eac9ad0>
gc: collectable <function 0x7ff04b942cf8>
gc: collectable <cell 0x7ff04b94a7f8>
gc: collectable <cell 0x7ff04b94a830>
gc: collectable <list 0x7ff04b9452d8>
gc: collectable <tuple 0x7ff04b9521b8>
gc: collectable <function 0x7ff04b942d70>
gc: collectable <StreamClosedError 0x7ff04b925808>
gc: collectable <tuple 0x7ff04b91ce50>
gc: collectable <tuple 0x7ff04b92ad70>
gc: collectable <functools.partial 0x7ff04b94d2b8>
gc: collectable <tuple 0x7ff04ea830d0>
gc: collectable <frame 0x7ff04b940050>
gc: collectable <frame 0x7ff04b935430>
gc: collectable <tuple 0x7ff04eb68dd0>
gc: collectable <frame 0x7ff04b8db050>
gc: collectable <frame 0xd90ca0>
gc: collectable <frame 0x7ff04b948750>
gc: collectable <frame 0x7ff04b953d70>
gc: collectable <traceback 0x7ff04b945f38>
gc: collectable <traceback 0x7ff04b945f80>
gc: collectable <traceback 0x7ff04b945b90>
gc: collectable <tuple 0x7ff04b92aaa0>
gc: collectable <traceback 0x7ff04b945fc8>
gc: collectable <traceback 0x7ff04b952170>
gc: collectable <tuple 0x7ff04caf6dc0>
gc: collectable <functools.partial 0x7ff04ca0a368>
gc: collectable <tuple 0x7ff04b92b790>
gc: collectable <frame 0x7ff04b8da608>
gc: collectable <frame 0x7ff04b956810>
gc: collectable <tuple 0x7ff04ca00ad0>
gc: collectable <frame 0x7ff04b8db730>
gc: collectable <frame 0xb0a4d0>
gc: collectable <frame 0x7ff04b955910>
gc: collectable <traceback 0x7ff04b8eacb0>
gc: collectable <traceback 0x7ff04b9058c0>
gc: collectable <tuple 0x7ff04b92af00>
gc: collectable <exceptions.StopIteration 0x7ff04b905950>
gc: done, 77 unreachable, 0 uncollectable, 0.0144s elapsed.

>>> Circular:
     <tornado.concurrent.Future object at 0x7ff04eb4f890>
     {'_tb_logger': None, '_result': None, '_done': True, '_callbacks': None, '_log_traceback': False, '_exc_info': (<class 'tornado.iostream.StreamClosedError'>, StreamClosedError('Stream is closed',), <traceback object at 0x7ff04b952170>)}
     (<class 'tornado.iostream.StreamClosedError'>, StreamClosedError('Stream is closed',), <traceback object at 0x7ff04b952170>)
     <traceback object at 0x7ff04b952170>
     <traceback object at 0x7ff04b945fc8>
     <traceback object at 0x7ff04b945b90>
     <traceback object at 0x7ff04b945f80>
     <traceback object at 0x7ff04b945f38>
     <frame object at 0x7ff04b953d70>
     <frame object at 0x7ff04b948750>
     <frame object at 0xd90ca0>
     (<class 'tornado.iostream.StreamClosedError'>, StreamClosedError('Stream is closed',), <traceback object at 0x7ff04b945b90>)
     <traceback object at 0x7ff04b945b90>

>>> Traceback:
  File "./memtest.py", line 60, in <module>
    ioloop.IOLoop.current().start()
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/ioloop.py", line 887, in start
    handler_func(fd_obj, events)
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/ioloop.py", line 621, in _run_callback
    self.handle_callback_exception(callback)
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    _state.contexts = current_state
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/gen.py", line 1104, in <lambda>
    self.future, lambda f: self.run())
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/gen.py", line 1056, in run
    self.running = False
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/concurrent.py", line 237, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 3, in raise_exc_info

>>> Traceback:
  File "./memtest.py", line 60, in <module>
    ioloop.IOLoop.current().start()
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/ioloop.py", line 887, in start
    handler_func(fd_obj, events)
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/ioloop.py", line 621, in _run_callback
    self.handle_callback_exception(callback)
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    _state.contexts = current_state
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/gen.py", line 1104, in <lambda>
    self.future, lambda f: self.run())
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/gen.py", line 1056, in run
    self.running = False
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/concurrent.py", line 237, in result
    raise_exc_info(self._exc_info)

>>> Traceback:
  File "./memtest.py", line 60, in <module>
    ioloop.IOLoop.current().start()
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/ioloop.py", line 887, in start
    handler_func(fd_obj, events)
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/ioloop.py", line 621, in _run_callback
    self.handle_callback_exception(callback)
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    _state.contexts = current_state
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/gen.py", line 1104, in <lambda>
    self.future, lambda f: self.run())
  File "/home/homm/env/env_ucare/local/lib/python2.7/site-packages/tornado/gen.py", line 1056, in run
    self.running = False

Most interesting objects are _HTTPRequestContext, HTTP1Connection, IOStream, StreamClosedError. And according to frame traces StreamClosedError is really raised somewhere.
So maybe there is the third issue somewhere.

Of course, this is not a leak, because number of uncollectable object is zero. But I think you agree that circular references make unwanted slowdown and memory consumption.

[aping-fo]

I also have memory leaks, when i use type : REPORTER_TYPE_SPAN_BATCH_LOG
dump the memory and i find many frame,traceback, timeouterror etc..

but change to REPORTER_TYPE_SPAN_LOG, there will have not that question why???????

[bdarnell]

I think you're asking in the wrong place this is an issue tracker for the tornado project (and an issue that was closed 5 years ago), and I don't know anything about these REPORTER constants you're referring to. If there is something related to tornado here, please open a new issue with more details.

[ndvbd]

I also have memory leaks when working with tornado.