Ignored ResourceWarning warnings leak memory in warnings registries

[ghost]

BPO	27535
Nosy	@rhettinger, @ncoghlan, @vstinner, @bitdancer, @serhiy-storchaka, @thehesiod, @AraHaan
PRs	bpo-27535: Fix memory leak with warnings ignore #4489 [WIP] bpo-27535: Optimize warnings #4502 bpo-27535: Optimize warnings.warn() #4508 bpo-27535: Cleanup create_filter() #4516 [3.6] bpo-27535: Fix memory leak with warnings ignore (GH-4489) #4587 [2.7] bpo-27535: Fix memory leak with warnings ignore #4588
Files	memory.py memory2.py bench_ignore_warn.py bench_c_warn.patch bench_ignore_warn_c.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vstinner'
closed_at = None
created_at = <Date 2016-07-17.01:53:42.897>
labels = ['3.7', 'expert-IO', 'performance']
title = 'Ignored ResourceWarning warnings leak memory in warnings registries'
updated_at = <Date 2018-05-23.21:26:16.382>
user = None

bugs.python.org fields:

activity = <Date 2018-05-23.21:26:16.382>
actor = 'vstinner'
assignee = 'vstinner'
closed = False
closed_date = None
closer = None
components = ['IO']
creation = <Date 2016-07-17.01:53:42.897>
creator = '\xd0\x90\xd0\xbb\xd0\xb5\xd0\xba\xd1\x81\xd0\xb0\xd0\xbd\xd0\xb4\xd1\x80 \xd0\x9a\xd0\xb0\xd1\x80\xd0\xbf\xd0\xb8\xd0\xbd\xd1\x81\xd0\xba\xd0\xb8\xd0\xb9'
dependencies = []
files = ['43762', '47281', '47282', '47286', '47287']
hgrepos = []
issue_num = 27535
keywords = ['patch']
message_count = 39.0
messages = ['270600', '270608', '270609', '270644', '270647', '270666', '306636', '306645', '306648', '306649', '306652', '306661', '306664', '306695', '306696', '306712', '306716', '306721', '306723', '306725', '306735', '306758', '306773', '306828', '306919', '306920', '306923', '307057', '307058', '307059', '307061', '307133', '307135', '307137', '307139', '307161', '307165', '317421', '317460']
nosy_count = 9.0
nosy_names = ['rhettinger', 'ncoghlan', 'vstinner', 'r.david.murray', 'serhiy.storchaka', 'thehesiod', 'Decorater', '\xd0\x90\xd0\xbb\xd0\xb5\xd0\xba\xd1\x81\xd0\xb0\xd0\xbd\xd0\xb4\xd1\x80 \xd0\x9a\xd0\xb0\xd1\x80\xd0\xbf\xd0\xb8\xd0\xbd\xd1\x81\xd0\xba\xd0\xb8\xd0\xb9', 'jbfzs']
pr_nums = ['4489', '4502', '4508', '4516', '4587', '4588']
priority = 'low'
resolution = None
stage = 'resolved'
status = 'open'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue27535'
versions = ['Python 3.7']

[ghost]

Actually, this issue is related to the warning module. The test script creates a lot of files with different names and deletes them. On the first pass the scripts calls the f.close() method for every file. On the second it doesn't.

As a result, on the first pass, the memory consumption is constant and is about 3.9 Mb for my environment. For the second pass, the memory consumption constantly grows up to 246 Mb for 1 million files. I.e. memory leak is about 254 bytes for every opened file.

This happens because of warning about not closed files. The memory is consumed for storing all possible warning messages generated for different file names to prevent further warnings with the same messages. Which is not the case if we are always opening new files.

While not calling f.close() **might** lead to memory issues, the warning which notifies about this **absolutely guaranteed** leads to memory issue. Although f.close() is highly recommended, this is still the issue for code which doesn't use it for some reasons and doesn't experience other problems with not closed files because files are actually always closed in IOBase.__del__.

This issue was discovered in this report: python-pillow/Pillow#2019

The best way to fix this is excluding file name from warning message. As a result, the message for every file will be the same and warnings registry will not grow. For now, the message looks like this:

./memory.py:23: ResourceWarning: unclosed file <_io.FileIO name='__999.tmp' mode='wb' closefd=True>
open_files(number, close)

It may looks like this:

./memory.py:23: ResourceWarning: unclosed file <FileIO mode='wb' closefd=True>
open_files(number, close)

[serhiy-storchaka]

The file name is helpful for determining the source of the leak. If you don't want to close files in your script, set an appropriate warning filter to silence this kind of warnings.

[ghost]

@serhiy.storchaka

Any filters not solves the problem because warnings module SAVES EVERY WARNING MESSAGE for further duplication checks.

Yes, the file name is helpful for determining the source of the POSSIBLE leak. While file name in error message IS SOURCE OF THE LEAK. When you aware about not closed files, you can log file names. You have a way to do that. But if you want to ignore the warning, the memory will leak. Not because of not closed files, but because of warning itself.

I do want to close files in my script, but in Pillow, it is not so easy due to backward compatibility.

[bitdancer]

I recommend rejecting this. Properly closing flies is the correct programming habit, which is why the ResourceWarning exists. The Pillow example seems to just indicate that people using Pillow need to pay attention to the ResourceWarning and close the files they open with pillow.

[serhiy-storchaka]

Thus, the problem is that even ignored warnings are saved. If there is a simple fix of this problem we can fix it. But if there is no simple and straightforward way, it may be not worth to complicate the code for such case. I'll look at the code.

[rhettinger]

I would like to see this fixed. It is rather unfortunate that a tool designed to help find possible resource leaks is itself a certain resource leak.

[jbfzs]

We just got hit by this. We had one specific case where files with unique names were not being closed and Python was leaking a lot of memory over a few days.

[vstinner]

The problem is not the function displaying the warning, but warnings registries (warningregistry) no?

The behaviour depends on the action of the filter matching the ResourceWarning warning:

• always: don't touch the registry => no leak
• ignore: add the key to registry => leak!
• another action: add the key to registry => leak!

The key is the tuple (text, category, lineno).

I understand why always doesn't touch the registry. But why does "ignore" action touch the registry? Not only the user will not see the message, but the memory will slowly grow in the background.

[vstinner]

I created PR 4489 to fix the memory leak for the "ignore "action". IMHO it's interesting to modify the "ignore" action because Python uses ignore many warnings by default:

haypo@selma$ python3 -c 'import pprint, warnings; pprint.pprint(warnings.filters)'
[('ignore', None, <class 'DeprecationWarning'>, None, 0),
('ignore', None, <class 'PendingDeprecationWarning'>, None, 0),
('ignore', None, <class 'ImportWarning'>, None, 0),
('ignore', None, <class 'BytesWarning'>, None, 0),
('ignore', None, <class 'ResourceWarning'>, None, 0)]

I created memory2.py (based on attached memory.py) to measure the leak.

Currently, the "always" action doesn't leak, but "ignore" and "default" actions leak:

haypo@selma$ ./python -W always memory2.py
Memory peak grow: +3.2 kB
Warning filters:
[('always',
re.compile('', re.IGNORECASE),
<class 'Warning'>,
re.compile(''),
0),
('ignore', None, <class 'BytesWarning'>, None, 0),
('always', None, <class 'ResourceWarning'>, None, 0)]

haypo@selma$ ./python -W ignore memory2.py
Memory peak grow: +26692.3 kB
Warning filters:
[('ignore',
re.compile('', re.IGNORECASE),
<class 'Warning'>,
re.compile(''),
0),
('ignore', None, <class 'BytesWarning'>, None, 0),
('always', None, <class 'ResourceWarning'>, None, 0)]

haypo@selma$ ./python -W default memory2.py
Memory peak grow: +26693.2 kB
Warning filters:
[('default',
re.compile('', re.IGNORECASE),
<class 'Warning'>,
re.compile(''),
0),
('ignore', None, <class 'BytesWarning'>, None, 0),
('always', None, <class 'ResourceWarning'>, None, 0)]

With my PR 4489, the "ignore" action doesn't leak anymore:

haypo@selma$ ./python -W ignore memory2.py
Memory peak grow: +2.4 kB
Warning filters:
[('ignore',
re.compile('', re.IGNORECASE),
<class 'Warning'>,
re.compile(''),
0),
('ignore', None, <class 'BytesWarning'>, None, 0),
('always', None, <class 'ResourceWarning'>, None, 0)]

[jbfzs]

@vstinner Yes, from what I saw, the leak was from the registry / deduplication logic.

[vstinner]

The best way to fix this is excluding file name from warning message. As a result, the message for every file will be the same and warnings registry will not grow.

Your warning comes from the io module which uses the message: "unclosed file %r" % file.

I dislike the idea of removing the filename from this warning message, since the filename is very useful to identify where the bug comes from.

Different things are discussed here:

• First of all, if an application is correctly written, ResourceWarning is not emitted, and so Python doesn't leak memory

• Using the "always" action, ResourceWarning doesn't leak neither.

• Using a different action like "default", ResourceWarning does leak memory in hidden warning registries.

While I don't see how we can avoid "leaking memory" (growing the registry) for actions like "once", I think that it's ok to don't touch the registry for the "ignore" action. So at least, an application ignoring ResourceWarning will not leak anymore.

But it will still "leak" when you display ResourceWarning warnings with an action different than "always". In this case, IMHO the root issue is more the code which doesn't close the resource, than Python itself.

[jbfzs]

But it will still "leak" when you display ResourceWarning warnings with an action different than "always". In this case, IMHO the root issue is more the code which doesn't close the resource, than Python itself.

Not closing a file is a bug, but under normal circumstances it causes no leak by itself. The fact that the warnings module leaks in this case seems a problem. Had I logged warnings correctly, I would have found the bug by looking at the application log rather than by investigating the cause of the OOM killer invocation.

IMHO, the warnings module should have upper bounds on memory consumption to avoid DOSing itself.

[serhiy-storchaka]

While I don't see how we can avoid "leaking memory" (growing the registry) for actions like "once", I think that it's ok to don't touch the registry for the "ignore" action. So at least, an application ignoring ResourceWarning will not leak anymore.

This is a caching for speed. If the same line of code emits the same warning, it is enough to tests the registry and don't apply all warning filters.

I think we should find better compromise between performance if all messages equal and memory usage if all messages are different. Since caching for the "ignore" action affects only performance, not semantic, we could check whether there are too much warnings for the "ignore" action are cached in the same line. The problem is how to make this effectively. And what is "too much".

[vstinner]

Attached bench_ignore_warn.py: microbenchmark (using the perf module) to measure the performance of emitting a warning when the warning is ignored.

I added two basic optimizations to my PR 4489. With these optimizations, the slowdown is +17% on such microbenchmark:

$ ./python -m perf compare_to ref.json patch.json 
Mean +- std dev: [ref] 903 ns +- 70 ns -> [patch] 1.06 us +- 0.06 us: 1.17x slower (+17%)

The slowdown was much larger without optimizations, +42%:

$ ./python -m perf compare_to ref.json ignore.json 
Mean +- std dev: [ref] 881 ns +- 59 ns -> [ignore] 1.25 us +- 0.08 us: 1.42x slower (+42%)

About the memory vs CPU tradeoff, we are talking around ~1000 ns. IMHO 1000 ns is "cheap" (fast) and emitting warnings is a rare event Python. I prefer to make warnings slower than "leaking" memory (current behaviour: warnings registry growing with no limit).

[AraHaan]

If it was me I would store the warning registry in an error log or something in the current directory that ran python itself. (maybe something like [main script name].log? This way it generates the warnings like usual and does not eat up memory. And then the log could to turned off when they dont want any warnings (when ignored).

[ncoghlan]

Touching the filesystem implicitly can have all sorts of unintentional side effects (especially in read-only environments), so we strongly prefer not to do that.

The most general solution here would be to turn the warnings registry into an LRU cache - short-lived applications wouldn't see any changes, while long-lived applications with changing warning messages would hit the upper bound and then stay there.

I also like Victor's change to have the "ignore" option skip touching the registry. If we decide we still want to optimise out the linear filter scan for those cases, then I'd suggest lazily building a dispatch table with separate per-category warnings filter lists (updating the dispatch table on the next emitted warning after the filter list changes), and then only falling back to scanning the full filter list for warning categories that aren't an exact match for anything in the dispatch table.

[serhiy-storchaka]

I think it is common if filters don't depend on the warning test. In this case we can test and set the key (None, category, lineno) before (text, category, lineno).

[vstinner]

$ ./python -m perf compare_to ref.json patch.json
Mean +- std dev: [ref] 903 ns +- 70 ns -> [patch] 1.06 us +- 0.06 us: 1.17x slower (+17%)

We are talking about a difference of 157 nanoseconds. On the same laptop, a Python function call which does nothing already takes 76.6 ns +- 4.1 ns. So the overhead of my PR 4489 is the cost of two Python function calls which do nothing. Do you think that it's an inacceptable overhead?

[vstinner]

The performance bottleneck of warnings.warn() is the dance between the C _warnings module and the Python warnings module. The C code retrieves many attributes, like warnings.filters, at each call, and does conversion from Python objects to C objects.

There is already a mecanism to invalidate a "cache" in the C module: warnings._filters_mutated() is called by warnings.filterwarnings() for example.

Maybe the C module could convert all filters at once into an efficient C structure, but throw this away once on cache invalidation.

The problem is that I'm not sure that it's ok to implement such deeper cache at C level. Is it part of the warnings "semantics" to allow users to modify directly warnings.filters? Must the C module always lookup in sys.modules if the 'warnings' modules didn't change?

Outside test_warnings, do you know an use case where lookup for the 'warnings' module and 'warnings.filters' must be done at *each* warnings.warn() call?

[vstinner]

I implemented a cache for warnings.filters in C. With my WIP patch which doesn't touch the registry for the ignore action, warnings.warn() is now faster than the current code ;-)

haypo@selma$ ./python -m perf compare_to ref.json patch.json
Mean +- std dev: [ref] 938 ns +- 72 ns -> [patch] 843 ns +- 57 ns: 1.11x faster (-10%)

There is a single test in test_warnings which modifies directly warnings.filters:

    @support.cpython_only
    def test_issue31416(self):
        # warn_explicit() shouldn't cause an assertion failure in case of a
        # bad warnings.filters or warnings.defaultaction.
        wmod = self.module
        with original_warnings.catch_warnings(module=wmod):
            wmod.filters = [(None, None, Warning, None, 0)]
            with self.assertRaises(TypeError):
                wmod.warn_explicit('foo', Warning, 'bar', 1)

            wmod.filters = []
            with support.swap_attr(wmod, 'defaultaction', None), \
                 self.assertRaises(TypeError):
                wmod.warn_explicit('foo', Warning, 'bar', 1)

I don't think that it's common to modify warnings.filters directly. Maybe we can make this sequence immutable in the public API to prevent misuse of the warnings API? To force users to use warnings.simplefilter() and warnings.filterwarnings()?

IMHO the main usage of modifying directyl warnings.filters it to save/restore filters. But there is already an helper for that: warnings.catch_warnings().

[vstinner]

I published my WIP work on optimizing warnings: PR 4502, it's based on PR 4489. The code should be cleaned up, especially the "_PyRuntime" part. The default action caching should be fixed.

[vstinner]

New changeset 8265627 by Victor Stinner in branch 'master':
bpo-27535: Optimize warnings.warn() (bpo-4508)
8265627

[vstinner]

My PR 4502 implements all optimizations, but also converts warnings.filters to a tuple, to detect when detect attempts to modify directly warnings.filters, rather than using function calls.

Problem: test.libregrtest module uses a pattern like this:

  old_filters = warnings.filters[:]  # in function 1
  (...)
  warnings.filters[:] = old_filters  # in function 2

While this pattern is perfectly fine when filters is a list, "warnings.filters[:] = old_filters" fails since a tuple is immutable.

Again, the question is if it's ok to break such code. I'm no more sure that catch_warnings() handles completly this use case, and a context manager is not convenient in the specific case of test.libregrest.

[vstinner]

New changeset b98f171 by Victor Stinner in branch 'master':
bpo-27535: Cleanup create_filter() (bpo-4516)
b98f171

[vstinner]

New benchmark on the emitting a warning which is ignored. Benchmark the PR 4489.

Warning emitted in Python, warnings.warn():

vstinner@apu$ ./python -m perf compare_to master.json ignore.json
Mean +- std dev: [master] 705 ns +- 24 ns -> [ignore] 838 ns +- 18 ns: 1.19x slower (+19%)

==> +133 ns

Warning emitted in C, PyErr_WarnEx():

vstinner@apu$ python3 -m perf compare_to master2.json ignore2.json
Mean +- std dev: [master2] 702 ns +- 9 ns -> [ignore2] 723 ns +- 9 ns: 1.03x slower (+3%)

==> +21 ns

C benchmark, attached files:

• bench_c_warn.patch
• bench_ignore_warn_c.py

[serhiy-storchaka]

These results look strange to me. I expected the same difference but smaller the base time.

[vstinner]

These results look strange to me. I expected the same difference but smaller the base time.

Honestly, I was also surprised.

I checked the whole benchmark twice. I also rebased the PR locally to make sure that it's not a side effect of a recent change in master.

Results are reliable and reproductible.

FYI I ran the C benchmark on my laptop "apu" using CPU isolation.

--

I reproduced the benchmark on my other "selma" laptop, without CPU isolation (so less reliable).

C benchmark:

haypo@selma$ python3 -m perf compare_to master.json ignore.json
Mean +- std dev: [master] 932 ns +- 66 ns -> [ignore] 1.01 us +- 0.05 us: 1.09x slower (+9%)

==> +78 ns

[vstinner]

New changeset c975878 by Victor Stinner in branch 'master':
bpo-27535: Fix memory leak with warnings ignore (bpo-4489)
c975878

[vstinner]

#4489 (comment)

Serhiy: "Could you please make a benchmark for warnings emitted in a tight loop in the C code. It would be nice to know what is the worst case. If it is less than 2x slower I will prefer this simpler PR."

I merged my PR since it's not 2x slower. I also prefer the simple PR 4489, rather than the complex PR 4502.

I rejected my PR 4502 since it's backward incompatible. I don't think that it's worth it, even if it's faster.

[serhiy-storchaka]

Thank you Victor!

[vstinner]

I consider that PR 4489 is a bugfix, so I proposed backports to Python 2.7 (PR 4588) and 3.6 (PR 4587).

[vstinner]

Victor: "I consider that PR 4489 is a bugfix, so I proposed backports to Python 2.7 (PR 4588) and 3.6 (PR 4587)."

Serhiy: Are you ok to backport the change to stable branches?

[serhiy-storchaka]

I'm not sure. Ask the RM for 3.6.

As for 2.7, does this problem exist in 2.7?

[vstinner]

Serhiy: "As for 2.7, does this problem exist in 2.7?"

Yes, see my PR 4588. If you run the test without the fix, the test fails.

[serhiy-storchaka]

I meant the original issue. AFAIK ResourceWarningis not raised in 2.7. And other warnings less likely have unique messages. Seems the problem is less critical in 2.7.

[vstinner]

Serhiy: "I meant the original issue. AFAIK ResourceWarningis not raised in 2.7. And other warnings less likely have unique messages. Seems the problem is less critical in 2.7."

Oh yes, sorry, I forgot your comment and I forgot that Python 2.7 doesn't have ResourceWarning. I closed my PR for Python 2.7: #4588

[vstinner]

I ran a quick benchmark on Python 3.6: current code (3.6 branch, ref) => PR 4587 (patch):

vstinner@apu$ python3 -m perf compare_to ref.json patch.json
Mean +- std dev: [ref] 597 ns +- 10 ns -> [patch] 830 ns +- 15 ns: 1.39x slower (+39%)

I don't want to backport an optimization to a stable branch, so I prefer to not backport the warnings change on the ignore action to Python 3.6. I rejected my PR 4587.

The bug was fixed in master. I don't want to backport the change to 2.7 nor 3.6, so I close the issue.

[thehesiod]

not fixing this means that 3.6 slowly leaks for many people in prod. It's not often possible to fix all the warnings on large dynamic applications, I highly suggest finding a way to get this into 3.6. I bet there are a lot of frustrated people out there who don't know why their applications slowly leak.

[vstinner]

Alexander Mohr reported a memory leak in his code using botocore (Python client for Amazon S3): bpo-33565. His code emited ResourceWarning, but these warnings are ignored by default. The link between ignored warnings and a memory leak is non obvious.

Serhiy: what do you think of backporting my _warnings change for the ignore action?

[iritkatriel]

Backport to 3.6 is no longer relevant.