Re: [Twisted-Python] Spurious commit/ticket links

[Jean-Paul Calderone]

On Sat, Dec 3, 2016 at 9:28 AM, Jean-Paul Calderone <
exar...@twistedmatrix.com> wrote:

> On Fri, Dec 2, 2016 at 9:28 PM, Glyph Lefkowitz 
> wrote:
>
>> > On Dec 2, 2016, at 4:49 PM, Jean-Paul Calderone <
>> exar...@twistedmatrix.com> wrote:
>> >
>> > I deployed this to production.  I don't see a good way to test it
>> without screwing around with twisted trunk ... so don't plan to.  I'll keep
>> an eye on real merges folks are working on and see if it's behaving as
>> desired.
>>
>> Thanks, JP!
>>
>> Would you mind updating https://twistedmatrix.com/trac
>> /wiki/ReviewProcess#Revertingachange and https://twistedmatrix.com/trac
>> /wiki/ReviewProcess#Authors:Howtomergethechangetotrunk to reflect the
>> new syntax that should be used on future merges?
>>
>>
> Updated.  As far as the behavior, do https://github.com/twisted/
> twisted/pull/614 / http://twistedmatrix.com/trac/ticket/8934 look right?
> The trac ticket is fixed but with no comment.  OTOH, I can't find the
> commit message for the PR merge so maybe that's as it should be?
>
>

Updated again.  Craig confirmed that it indeed wasn't working (at all).

Also, the site's now running trac 1.2 (was 1.0.12).  The fab target for
re-deploying trac just picks the newest release at the moment, despite the
*appearance* of being pinned to a particular version.  I don't think I'm
going to try to bite off fixing this.  The problem, though, is multiple
invocations of `pip -U` - a later instance of which is totally happy to
upgrade the trac 1.0.12 install to 1.2.

Jean-Paul



> -glyph
>>
>>
>> ___
>> Twisted-Python mailing list
>> Twisted-Python@twistedmatrix.com
>> http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
>>
>
>
___
Twisted-Python mailing list
Twisted-Python@twistedmatrix.com
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

Re: [Twisted-Python] memory leaks

[Glyph Lefkowitz]

> On Dec 4, 2016, at 9:50 AM, Jean-Paul Calderone  
> wrote:
> 
> On Sun, Dec 4, 2016 at 12:50 AM, Glyph Lefkowitz  > wrote:
> 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.

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

___
Twisted-Python mailing list
Twisted-Python@twistedmatrix.com
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

Re: [Twisted-Python] Spurious commit/ticket links

[Glyph Lefkowitz]

> On Dec 5, 2016, at 2:45 PM, Jean-Paul Calderone  
> wrote:
> 
> On Sat, Dec 3, 2016 at 9:28 AM, Jean-Paul Calderone 
> mailto:exar...@twistedmatrix.com>> wrote:
> On Fri, Dec 2, 2016 at 9:28 PM, Glyph Lefkowitz  > wrote:
> > On Dec 2, 2016, at 4:49 PM, Jean-Paul Calderone  > > wrote:
> >
> > I deployed this to production.  I don't see a good way to test it without 
> > screwing around with twisted trunk ... so don't plan to.  I'll keep an eye 
> > on real merges folks are working on and see if it's behaving as desired.
> 
> Thanks, JP!
> 
> Would you mind updating 
> https://twistedmatrix.com/trac/wiki/ReviewProcess#Revertingachange 
>  and 
> https://twistedmatrix.com/trac/wiki/ReviewProcess#Authors:Howtomergethechangetotrunk
>  
> 
>  to reflect the new syntax that should be used on future merges?
> 
> 
> Updated.  As far as the behavior, do 
> https://github.com/twisted/twisted/pull/614 
>  / 
> http://twistedmatrix.com/trac/ticket/8934 
>  look right? The trac ticket is 
> fixed but with no comment.  OTOH, I can't find the commit message for the PR 
> merge so maybe that's as it should be?
>  
> 
> Updated again.  Craig confirmed that it indeed wasn't working (at all).
> 
> Also, the site's now running trac 1.2 (was 1.0.12).  The fab target for 
> re-deploying trac just picks the newest release at the moment, despite the 
> appearance of being pinned to a particular version.  I don't think I'm going 
> to try to bite off fixing this.  The problem, though, is multiple invocations 
> of `pip -U` - a later instance of which is totally happy to upgrade the trac 
> 1.0.12 install to 1.2.

Now I can't create tickets at all.  I hope this is related and not just general 
decay of our Trac instance :).

The web UI tells me "Warning: The action "None" is not available" without 
actually creating the ticket.  Nothing that I can see appears in the logs.  
Hopefully this warning message means something to someone?

-glyph


___
Twisted-Python mailing list
Twisted-Python@twistedmatrix.com
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

Re: [Twisted-Python] memory leaks

[Amber "Hawkie" Brown]

> On 6 Dec. 2016, at 17:09, Glyph Lefkowitz  wrote:
> 
> 
> 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 


- Amber___
Twisted-Python mailing list
Twisted-Python@twistedmatrix.com
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

Re: [Twisted-Python] memory leaks

[Glyph Lefkowitz]

> On Dec 5, 2016, at 10:18 PM, Amber Hawkie Brown  
> wrote:
> 
> 
>> On 6 Dec. 2016, at 17:09, Glyph Lefkowitz > > wrote:
>> 
>> 
>> 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!

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

trac@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

___
Twisted-Python mailing list
Twisted-Python@twistedmatrix.com
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python