[Twisted-Python] memory leaks

[Glyph Lefkowitz]

Following up on a Stack Overflow question from some time ago, http://stackoverflow.com/questions/40604545/twisted-using-connectprotocol-to-connect-endpoint-cause-memory-leak?noredirect=1#comment68573508_40604545 since the submitter added a minimal reproducer, I used Heappy https://pypi.org/project/guppy/ to look at memory sizing, and seeing large numbers of Logger instances and type objects leaking when using client endpoints. It was not immediately obvious to me where the leak is occurring though, as I was careful to clean up the Deferred results and not leave them in a failure state.

I am hoping that I can entice someone else to diagnose this far enough to actually file a bug :-).

-glyph

[Jean-Paul Calderone]

Post by Glyph Lefkowitz
Following up on a Stack Overflow question from some time ago,
http://stackoverflow.com/questions/40604545/twisted-
using-connectprotocol-to-connect-endpoint-cause-memory-leak?noredirect=1#
comment68573508_40604545 since the submitter added a minimal reproducer,
I used Heappy https://pypi.org/project/guppy/ to look at memory sizing,
and seeing large numbers of Logger instances and type objects leaking when
using client endpoints. It was not immediately obvious to me where the
leak is occurring though, as I was careful to clean up the Deferred results
and not leave them in a failure state.
I am hoping that I can entice someone else to diagnose this far enough to
actually file a bug :-).

Answered. I didn't file a bug, I'll let someone else with ideas about
twisted.logger think about what exactly the bug is.

Jean-Paul

[Glyph Lefkowitz]

Following up on a Stack Overflow question from some time ago, http://stackoverflow.com/questions/40604545/twisted-using-connectprotocol-to-connect-endpoint-cause-memory-leak?noredirect=1#comment68573508_40604545 <http://stackoverflow.com/questions/40604545/twisted-using-connectprotocol-to-connect-endpoint-cause-memory-leak?noredirect=1#comment68573508_40604545> since the submitter added a minimal reproducer, I used Heappy https://pypi.org/project/guppy/ <https://pypi.org/project/guppy/> to look at memory sizing, and seeing large numbers of Logger instances and type objects leaking when using client endpoints. It was not immediately obvious to me where the leak is occurring though, as I was careful to clean up the Deferred results and not leave them in a failure state.
I am hoping that I can entice someone else to diagnose this far enough to actually file a bug :-).
Answered. I didn't file a bug, I'll let someone else with ideas about twisted.logger think about what exactly the bug is.

I wrote up this bug, and will file it when the ability to file bugs on Trac comes back:

twisted.logger._initialBuffer can consume a surprisingly large amount of memory if logging is not initialized


The way that `twisted.logger` is supposed to work is that at process startup time, the global log observer has a ring buffer for any messages emitted before logging is initialized, and emit those messages to the initial set of log observers passed to `globalLogBeginner.beginLoggingTo`.

The size of this buffer (in `twisted.logger._buffer._DEFAULT_BUFFER_MAXIMUM` is 65535. This value was selected arbitrarily, probably because somebody (me or wsanchez) thought "huh, yeah, 64k, that's probably a fine number); but of course, that's 64k ''bytes''.

If this were a buffer of actual formatted log messages, of say 200 bytes each, that would be about 13 megabytes, which is maybe an acceptable amount of RAM to spend on a log buffer.

However, it isn't that. It's a buffer of 64k log ''events'', each of which probably has a `log_logger` and `log_source` set, each of which is an object attached to potentially arbitrary data. For example, every `Factory` that starts up logs something, which means you're holding on to an instance, and an instance dictionary, and the protocol instance, and the protocol instance dictionary. Worse yet, any logged ''failures'' might hold on to all the stuff on their stack.

Add it all up and you end up with a log buffer totaling in the hundreds of megabytes, or even gigabytes, once it's full. In an application that naively uses Twisted without ever initializing logging, this hangs around forever.

This buffer should probably be a ''lot'' smaller, and we might want to emit a warning when it fills up, reminding people that it is ''only polite'' to start up the logging subsystem, even just to explicitly throw logs away.

Text is here in case someone else manages to make trac come back and would like to file it before I get back :).

-glyph

[Amber "Hawkie" Brown]

Post by Glyph Lefkowitz
twisted.logger._initialBuffer can consume a surprisingly large amount of memory if logging is not initialized
The way that `twisted.logger` is supposed to work is that at process startup time, the global log observer has a ring buffer for any messages emitted before logging is initialized, and emit those messages to the initial set of log observers passed to `globalLogBeginner.beginLoggingTo`.
The size of this buffer (in `twisted.logger._buffer._DEFAULT_BUFFER_MAXIMUM` is 65535. This value was selected arbitrarily, probably because somebody (me or wsanchez) thought "huh, yeah, 64k, that's probably a fine number); but of course, that's 64k ''bytes''.
If this were a buffer of actual formatted log messages, of say 200 bytes each, that would be about 13 megabytes, which is maybe an acceptable amount of RAM to spend on a log buffer.
However, it isn't that. It's a buffer of 64k log ''events'', each of which probably has a `log_logger` and `log_source` set, each of which is an object attached to potentially arbitrary data. For example, every `Factory` that starts up logs something, which means you're holding on to an instance, and an instance dictionary, and the protocol instance, and the protocol instance dictionary. Worse yet, any logged ''failures'' might hold on to all the stuff on their stack.
Add it all up and you end up with a log buffer totaling in the hundreds of megabytes, or even gigabytes, once it's full. In an application that naively uses Twisted without ever initializing logging, this hangs around forever.
This buffer should probably be a ''lot'' smaller, and we might want to emit a warning when it fills up, reminding people that it is ''only polite'' to start up the logging subsystem, even just to explicitly throw logs away.

I fixed trac: https://twistedmatrix.com/trac/ticket/8936#ticket <https://twistedmatrix.com/trac/ticket/8936#ticket>

- Amber

[Glyph Lefkowitz]

Post by Amber "Hawkie" Brown

Post by Glyph Lefkowitz
twisted.logger._initialBuffer can consume a surprisingly large amount of memory if logging is not initialized
The way that `twisted.logger` is supposed to work is that at process startup time, the global log observer has a ring buffer for any messages emitted before logging is initialized, and emit those messages to the initial set of log observers passed to `globalLogBeginner.beginLoggingTo`.
The size of this buffer (in `twisted.logger._buffer._DEFAULT_BUFFER_MAXIMUM` is 65535. This value was selected arbitrarily, probably because somebody (me or wsanchez) thought "huh, yeah, 64k, that's probably a fine number); but of course, that's 64k ''bytes''.
If this were a buffer of actual formatted log messages, of say 200 bytes each, that would be about 13 megabytes, which is maybe an acceptable amount of RAM to spend on a log buffer.
However, it isn't that. It's a buffer of 64k log ''events'', each of which probably has a `log_logger` and `log_source` set, each of which is an object attached to potentially arbitrary data. For example, every `Factory` that starts up logs something, which means you're holding on to an instance, and an instance dictionary, and the protocol instance, and the protocol instance dictionary. Worse yet, any logged ''failures'' might hold on to all the stuff on their stack.
Add it all up and you end up with a log buffer totaling in the hundreds of megabytes, or even gigabytes, once it's full. In an application that naively uses Twisted without ever initializing logging, this hangs around forever.
This buffer should probably be a ''lot'' smaller, and we might want to emit a warning when it fills up, reminding people that it is ''only polite'' to start up the logging subsystem, even just to explicitly throw logs away.

I fixed trac: https://twistedmatrix.com/trac/ticket/8936#ticket <https://twistedmatrix.com/trac/ticket/8936#ticket>

Thanks!

By "Fixed" I take it you mean rolled back, via:

***@dornkirk:~$ ./virtualenv/bin/pip freeze | grep Trac==
Trac==1.0.13

and
https://github.com/twisted-infra/braid/commit/c2d393fd501c6464b1b475eff214cab64f13ee2a

Don't get me wrong, I'm not complaining :). This is certainly the right thing to do for now. But I'm wondering if you know what's wrong with 1.2 so we can upgrade soonish?

-glyph

[bret curtis]

Isn't this a duplicate of my "memory leak" bug report from about 11 months ago?
https://twistedmatrix.com/trac/ticket/8164

Glype's last comment on the ticket was:
Now, again, I want to be clear that the buffer size here is still a
bug, and we vastly mis-estimated a reasonable size.

The end result was that Hawkie indicated that there was a 64K buffer
of variable length logs. Because they are variable in length means
they use either almost no memory to potentially causing the OOM to
come along. What wasn't clear was if you reached the 64K limit, does
Twisted then just drop the rest of the logs are is the buffer a
circular one and drops the first entry to accommodate the last entry
or something else entirely?

Cheers,
Bret

Post by Glyph Lefkowitz
twisted.logger._initialBuffer can consume a surprisingly large amount of
memory if logging is not initialized
The way that `twisted.logger` is supposed to work is that at process startup
time, the global log observer has a ring buffer for any messages emitted
before logging is initialized, and emit those messages to the initial set of
log observers passed to `globalLogBeginner.beginLoggingTo`.
The size of this buffer (in `twisted.logger._buffer._DEFAULT_BUFFER_MAXIMUM`
is 65535. This value was selected arbitrarily, probably because somebody
(me or wsanchez) thought "huh, yeah, 64k, that's probably a fine number);
but of course, that's 64k ''bytes''.
If this were a buffer of actual formatted log messages, of say 200 bytes
each, that would be about 13 megabytes, which is maybe an acceptable amount
of RAM to spend on a log buffer.
However, it isn't that. It's a buffer of 64k log ''events'', each of which
probably has a `log_logger` and `log_source` set, each of which is an object
attached to potentially arbitrary data. For example, every `Factory` that
starts up logs something, which means you're holding on to an instance, and
an instance dictionary, and the protocol instance, and the protocol instance
dictionary. Worse yet, any logged ''failures'' might hold on to all the
stuff on their stack.
Add it all up and you end up with a log buffer totaling in the hundreds of
megabytes, or even gigabytes, once it's full. In an application that
naively uses Twisted without ever initializing logging, this hangs around
forever.
This buffer should probably be a ''lot'' smaller, and we might want to emit
a warning when it fills up, reminding people that it is ''only polite'' to
start up the logging subsystem, even just to explicitly throw logs away.
I fixed trac: https://twistedmatrix.com/trac/ticket/8936#ticket
Thanks!
Trac==1.0.13
and
https://github.com/twisted-infra/braid/commit/c2d393fd501c6464b1b475eff214cab64f13ee2a
Don't get me wrong, I'm not complaining :). This is certainly the right
thing to do for now. But I'm wondering if you know what's wrong with 1.2 so
we can upgrade soonish?
-glyph
_______________________________________________
Twisted-Python mailing list
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

[Glyph Lefkowitz]

Post by bret curtis
Isn't this a duplicate of my "memory leak" bug report from about 11 months ago?
https://twistedmatrix.com/trac/ticket/8164

Yes, thank you for the reference to that. I've closed the new one and updated the old one.

Post by bret curtis
Now, again, I want to be clear that the buffer size here is still a
bug, and we vastly mis-estimated a reasonable size.

Apparently my opinion hasn't changed, although I didn't remember it ;).

Post by bret curtis
The end result was that Hawkie indicated that there was a 64K buffer
of variable length logs. Because they are variable in length means
they use either almost no memory to potentially causing the OOM to
come along. What wasn't clear was if you reached the 64K limit, does
Twisted then just drop the rest of the logs are is the buffer a
circular one and drops the first entry to accommodate the last entry
or something else entirely?

It's intended to be a ring buffer, yes, so it should drop the earlier ones. A PR to shrink the default to something reasonable based on your measurements would be very helpful :).

-glyph