[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

this is how my friends talk here, see: 
https://english.stackexchange.com/questions/11816/is-guy-gender-neutral

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

of course, sorry, I meant in a gender neutral way

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Mariatta Wijaya]

Mariatta Wijaya  added the comment:

Alexander, in the future please use gender-neutral words such as "folks" and 
"y'all" instead of "guys". Thanks.

--
nosy: +Mariatta

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

ok fair enough, however a caveat is that it's not necessarily end of function 
as I was able to expand the function by a few more lines and the callstack 
stayed the same, however I'm guessing the interpreter was smart enough to 
realize the calls below the try/except had no references.  

it would be nice if there was a virtual "socket.__del__` or something at the 
end of the stack.  Basically if it could plug into the extension callbacks.  
That way we could have a little more visibility.

closing, thanks guys. This fixes the issue in botocore, on to the next related 
leak found via aiobotocore in aiohttp, where it now has no tracemalloc entries, 
so I'm guessing a leak via the ssl module to openssl :(

thanks again guys for the help, I really appreciate it, I hope in the future, 
my some mechanism, scenarios like these will be a lot easier to decipher.

--
resolution:  -> not a bug
stage:  -> resolved
status: open -> closed

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

INADA Naoki  added the comment:

> The callstack I initially mentioned still has no explanation and we now know 
> is not correct.

I don't think so.
The callstack is Python's callstack where caused leak in C.  (Python doesn't 
call malloc directly)

In this case, local variables are freed "at end of the function", and it freed 
unclosed socket which cause warning. (*)
So the callstack is completely valid.  While only CPython expert can understand.

(*) or "at the end of the except clause" which frees `e` and `e` have reference 
to the unclosed socket.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

actually, thinking about this more on my way to work, this should NOT be 
closed.  The callstack I initially mentioned still has no explanation and we 
now know is not correct.  It should either have listed something related to 
warnings, or nothing at all () or something like that.

There is no documentation to describe this behavior, think about it, it would 
have to be something like:

"tracemalloc may give completely irrelevant callstacks".  

So I think this callstack still needs to be explained, and either:

1) the module should be fixed so it would give something more relevant (to give 
developers some foothold to realize this was related to warnings

2) For this scenario the callstack should be removed, to inform the developer 
that they should manually track the allocations in gdb or with some other 
mechanism.

It would be really nice to know what c-callstacks (with parameters) trigger 
this tracemalloc stack.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

Ok I've verified that the patch does indeed fix the leak detected.  Thank you 
very much INADA for knowing that there was a leak in the warnings module, I 
would have never guessed, especially given the tracemalloc stack given.  Had it 
showed a callstack where the warning was created it would have made a lot more 
sense.

I agree this can be closed, however can the leak fix PLEASE be put into 3.6 
(any any other version that needs it)?  Who cares if warnings are 1.4x slower 
with the fix?  Are you going to rationally tell me that keeping warnings fast 
is more important than fixing leaks? In most applications there should be no 
warnings so it doesn't really matter. This particular leak was causing our 
application to fail after running for a few days which makes it unusable in 
production.  It's caused me a lot of days wasted in investigation.  If speed 
was really a problem that would have been a much worthier thing to spend time 
on than finding leaks.

leaks should be highest priority, then speed.  No rational developer would have 
complained that warnings got slower, that's when you fix warnings, not because 
of leaks! :)

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

I'll try with that fix and see if the leak is fixed, is the reasoning that if 
the warning happens after the try/except scope and that's why the callstack has 
it?

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

> Hmm, GH-4587 is merged in 3.6 branch in last November, but 3.6.5 doesn't 
> include it?

We decided to not fix the memory leak in Python 3.6:
https://github.com/python/cpython/pull/4587#issuecomment-347659163

"""
This change makes warning.warn() 1.4x slower on Python 3.6 for the ignore 
action: https://bugs.python.org/issue27535#msg307165

I don't think that the memory leak issue is important enough to justify such 
slowdown in a stable branch. So I close my PR.
"""

So yes, this issue is a bug in Python: it's bpo-27535. It's a bug in the 
_warnings module. tracemalloc only tells you the truth, it's just that it's 
hard to understand the output :-)

The bug occurs when you get ResourceWarning warnings. Such warning means that 
the code has a bug: the bug should be fixed. If you fix the ResourceWarning, 
the bug should disappear.

As Naoki INADA wrote: use python3 -Walways (I prefer python3 -Wdefault, but 
it's almost the same ;-)) to see such warnings.

Python 3.7 comes with a new -X dev option which enables these warnings but also 
other runtime checks to ease development.

I suggest to close this issue as a duplicate of bpo-27535.

Thanks Alexander Mohr for your bug report, and good luck to fix your warning 
;-) If you are motivated, you can propose changes to the tracemalloc 
documentation!

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

INADA Naoki  added the comment:

I was wrong.  It is not merged into 3.6 branch.
The pull request is just closed.

Now nothing strange in tracemalloc.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Antoine Pitrou]

Change by Antoine Pitrou :


--
nosy:  -pitrou

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

INADA Naoki  added the comment:

Hmm, GH-4587 is merged in 3.6 branch in last November, but 3.6.5 doesn't 
include it?

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

INADA Naoki  added the comment:

I confirmed the leak on 3.6.5, and I can't reproduce it on 3.7.0b4.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

> Thanks, I can reproduce.

Are you testing the master branch? I fixed a memory leak in the _warnings 
module for ignored ResourceWarning warnings.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

INADA Naoki  added the comment:

Alexander Mohr:

Thanks, I can reproduce.

I found ResourceWarning is happened when head_object.
re may be used for filtering warning.

You can use `-W always` to see the warnings.

I don't know why the leak happened yet.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

INADA Naoki: Unfortunately you'll need to use credentials from a free AWS 
account: https://aws.amazon.com/free/.  Then create a credentials file in 
~/.aws/credentials: 
https://docs.aws.amazon.com/cli/latest/userguide/cli-config-files.html

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

INADA Naoki  added the comment:

I can't reproduce it:

  File "test1.py", line 19, in do_get_obj
response = s3_client.get_object(Bucket='archpi.dabase.com', Key='style.css')
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/client.py",
 line 314, in _api_call
return self._make_api_call(operation_name, kwargs)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/client.py",
 line 599, in _make_api_call
operation_model, request_dict)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/endpoint.py",
 line 148, in make_request
return self._send_request(request_dict, operation_model)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/endpoint.py",
 line 173, in _send_request
request = self.create_request(request_dict, operation_model)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/endpoint.py",
 line 157, in create_request
operation_name=operation_model.name)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/hooks.py",
 line 227, in emit
return self._emit(event_name, kwargs)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/hooks.py",
 line 210, in _emit
response = handler(**kwargs)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/signers.py",
 line 90, in handler
return self.sign(operation_name, request)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/signers.py",
 line 156, in sign
auth.add_auth(request)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/auth.py",
 line 420, in add_auth
super(S3SigV4Auth, self).add_auth(request)
  File 
"/Users/inada-n/tmp/boto-leak/venv/lib/python3.6/site-packages/botocore/auth.py",
 line 352, in add_auth
raise NoCredentialsError
botocore.exceptions.NoCredentialsError: Unable to locate credentials

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

yes, memory does go up.  If you click the botocore bug link you'll see a graph 
of memory usage over time.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

> this means 21 blocks were not released, and in this case leaked because 
> nothing should be held onto after the first iteration (creating the initial 
> connector in the connection pool.  In the head object case that's going to be 
> a new connector per iteration, however the old one should go away.

I'm not sure that I understand properly. If you call the function many times, 
does the memory usage increase?

I'm not sure that this issue is a bug in Python.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

that's not going to affect 
http://pytracemalloc.readthedocs.io/api.html#get_traced_memory.  There is no 
filter for that :)

as to your sum that's exactly what my original callstack lists:
21 memory blocks: 4.7 KiB

this means 21 blocks were not released, and in this case leaked because nothing 
should be held onto after the first iteration (creating the initial connector 
in the connection pool.  In the head object case that's going to be a new 
connector per iteration, however the old one should go away.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

Oh. Usually, I strip traces allocated by tracemalloc using filters:

http://pytracemalloc.readthedocs.io/examples.html#pretty-top

snapshot = snapshot.filter_traces((
tracemalloc.Filter(False, ""),
tracemalloc.Filter(False, ""),
))

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

I believe your method is flawed, when enabling tracemalloc it's going to be 
using memory as well to store the traces.  I still believe you need to use the 
method I mentioned and further even if we don't take into account the total 
memory the traces I mentioned need to be explained.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

A memory leak is when each iteration adds a fixed number of bytes of the 
memory: I'm talking about tracemalloc.get_traced_memory()[0] value. For 
example, if you compare the total traced memory between your iteration 30 and 
iteration 20, you get a value 10N. If you compare iteration 100 and 20, I would 
expect the value 80N. Is it the case?

You can get the number of allocated bytes from a snapshot using:

>>> sum(trace.size for trace in snapshot.traces)
2620350

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[INADA Naoki]

Change by INADA Naoki :


--
nosy: +inada.naoki

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

here's another problem, if I change that function signature to:
def test(s3_client):
try:
method = getattr(s3_client, sys.argv[1])
method(Bucket='archpi.dabase.com', Key='doesnotexist')
except botocore.exceptions.ClientError as e:
if e.response['ResponseMetadata']['HTTPStatusCode'] != 404:
raise 

print('.', end='', flush=True)

the print happens every time and the raise does not ever get hit, yet the raise 
line is still marked as the top "leak" (unfreed blocks).  It's really strange.  
Furthermore the second top "leak" is this stack:
  File "/tmp/Python-3.6.5/Lib/sre_compile.py", line 439
return prefix, prefix_skip, False
  File "/tmp/Python-3.6.5/Lib/sre_compile.py", line 498
prefix, prefix_skip, got_all = _get_literal_prefix(pattern)
  File "/tmp/Python-3.6.5/Lib/sre_compile.py", line 548
_compile_info(code, p, flags)


which doesn't make sense either, why would the return line be marked as having 
allocated anything?

and btw I did change the implementation to start early, and then compare 
differences between a snapshot at iter 20 and iter 100 and the same holds true 
as I stated, there should logically be no difference between starting it later, 
or starting in the beginning and comparing two snapshots as all what you're 
doing in either cases is comparing two

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

actually it does show in 3.5.2, it doesn't show when using get_object, but it 
does when using head_object, and they both throw the same exception, so weird.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

so based on my last comment I just realized we could easily see if something 
was amiss by comparing results from python 3.5.2 to 3.6.5 and low and behold 
the callstack in question does not appear in the tracemalloc results from 3.5.2.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

I realize it doesn't track leaks, it's a tool to help find leaks when used 
correctly :)  This example should be similar to using the compare snapshots 
mechanism as I start tracking from a stable point (several iterations in after 
a gc), and then compare to another stable point several iterations later.  I 
have a much more complicated set-up at our company but wanted to keep the 
example as short as people complain here about large examples.

Further I realize how tracemalloc works, I have a lot of experience in leak 
hunting from my c++ days, I've even written my own native version of 
tracemalloc before (it's not hard).

The top stat is what bubbles up as the largest leak after a number of runs, 
that's why the results are so peculiar.  I've used tracemalloc before to find 
https://bugs.python.org/issue29870 in 3.5.2 and there the results made sense, 
here it makes no sense.  To my understanding there should not be any interned 
strings or other items that would cause this particular callstack to be the top 
hit of unreleased blocks of memory (leaks).

I still don't see any credible reason from why that callstack would be 
returned.  I still believe there's a real bug here, perhaps there's a leak 
inside the python interpreter implementation it's trying to point out?  I think 
it's worth investigating.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

tracemalloc doesn't track memory leaks. It tracks memory allocations.

I'm not sure that you are using tracemalloc properly. I suggest you to enable 
tracemalloc as soon as possible, take snapshot frequently (eg. at each 
iteration) and write them on disk, and later compute differences between 
snapshots.

You may want to try my tracemallocqt UI to analyze snapshots:
http://pytracemalloc.readthedocs.io/tracemallocqt.html

What matters to track a memory leak is to find the largest positive difference.

I don't know what allocated "21 memory blocks: 4.7 KiB" at your "raise" line. 
tracemalloc tracks *all* memory allocated by Python, including very private 
internal structures, like the dictionary used for "interned" strings. 
Sometimes, results can be surprising, but it should be simpler if you focus on 
differences between two snapshots.

If you have a leak per iteration, after 10 or 25 iterations, the difference 
should become obvious.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[STINNER Victor]

STINNER Victor  added the comment:

Once you found and fixed your memory leak, any documentation enhancement is 
welcome :-)

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Alexander Mohr  added the comment:

here's a version that tries to do something similar but does not reproduce the 
issue

--
Added file: https://bugs.python.org/file47602/tracemalloc_test2.py

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Antoine Pitrou]

Antoine Pitrou  added the comment:

Can you post a reproducer that doesn't involve S3?

--
nosy: +pitrou

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Andrew Svetlov]

Andrew Svetlov  added the comment:

Victor, could you take a look?

--
nosy: +asvetlov, vstinner

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

Change by Alexander Mohr :


--
type:  -> behavior

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue33565] strange tracemalloc results

[Alexander Mohr]

New submission from Alexander Mohr :

while investigating https://github.com/boto/botocore/issues/1464 I used 
tracemalloc (like I've done before in 3.5.2) to try to figure out where the 
leak was.  To my surprise tracemalloc listed stacks that didn't make any sense.


Strangest example is the top result when running the attached script against 
python 3.6.5 in the following manner: PYTHONMALLOC=malloc /valgrind/bin/python3 
/tmp/test.py head_object

The top hit is listed as:

21 memory blocks: 4.7 KiB
  File "/tmp/test.py", line 28
raise
  File "/tmp/test.py", line 47
test(s3_client)
  File "/tmp/test.py", line 65
main()

how is it that the "raise" is a leak?  It doesn't make any sense to me 
specially given that no contexts are used in that call.  Further that line is 
never hit because the exception is not re-thrown.


Further a bunch of regular expression allocs don't make any sense either given 
that I've cleared the cache before doing snapshots.

if someone could shed some light on why this is/isn't a bug that would be 
great.  It seems to me that the callstacks are not related at all to the leak.

--
components: Library (Lib)
files: tracemalloc_test.py
messages: 317002
nosy: thehesiod
priority: normal
severity: normal
status: open
title: strange tracemalloc results
versions: Python 3.6
Added file: https://bugs.python.org/file47600/tracemalloc_test.py

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com