logging: some optimizations #7214

bluetech · 2020-05-12T12:17:28Z

Please see the commit messages for details.

On this benchmark:

import pytest
@pytest.mark.parametrize("x", range(5000))
def test_foo(x): pass

Before (only relevant entries shown):

============================ 5000 passed in 14.13s =============================
         13465818 function calls (12550967 primitive calls) in 14.571 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
140003/60003 0.109    0.000    2.435    0.000 contextlib.py:108(__enter__)
    80000    0.098    0.000    2.224    0.000 logging.py:618(_runtest_for)
140003/60003 0.143    0.000    2.194    0.000 contextlib.py:117(__exit__)
    80000    0.257    0.000    1.721    0.000 logging.py:627(_runtest_for_main)
    30000    0.046    0.000    0.972    0.000 logging.py:685(pytest_runtest_logreport)
    40000    0.096    0.000    0.711    0.000 logging.py:302(__init__)
    10000    0.014    0.000    0.456    0.000 logging.py:668(pytest_runtest_teardown)
    80000    0.137    0.000    0.434    0.000 logging.py:271(catching_logs)
    10000    0.017    0.000    0.323    0.000 logging.py:673(pytest_runtest_logstart)
    10000    0.014    0.000    0.301    0.000 logging.py:680(pytest_runtest_logfinish)
    10000    0.013    0.000    0.285    0.000 logging.py:658(pytest_runtest_setup)
    10000    0.012    0.000    0.258    0.000 logging.py:663(pytest_runtest_call)

After:

============================ 5000 passed in 11.86s =============================
         10476806 function calls (9908460 primitive calls) in 12.164 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    35003    0.053    0.000    1.430    0.000 contextlib.py:117(__exit__)
    35003    0.037    0.000    1.155    0.000 contextlib.py:108(__enter__)
    30000    0.143    0.000    0.563    0.000 logging.py:622(_runtest_for)
    30000    0.067    0.000    0.223    0.000 logging.py:275(catching_logs)
    10000    0.020    0.000    0.222    0.000 logging.py:647(pytest_runtest_setup)
    10000    0.024    0.000    0.222    0.000 logging.py:657(pytest_runtest_teardown)
    10000    0.011    0.000    0.184    0.000 logging.py:653(pytest_runtest_call)
    15000    0.006    0.000    0.006    0.000 logging.py:675(pytest_runtest_logreport)
     5000    0.003    0.000    0.003    0.000 logging.py:663(pytest_runtest_logstart)
     5000    0.003    0.000    0.003    0.000 logging.py:670(pytest_runtest_logfinish)

bluetech · 2020-05-12T15:20:43Z

The test failure is legitimate, so this needs some more work.

This makes things type-safe.

This avoids a little bit of overhead, and makes the code a bit clearer too.

Avoid the slight overhead of contextmanager.

… create Previously, a LoggingCaptureHandler was instantiated for each test's setup/call/teardown/logstart/logfinish/logreport which turns out to be expensive. Instead, only keep one instance and reset it between runs.

The logstart/logreport/logfinish hooks don't need the stuff in _runtest_for: - All of the item-conditional sections are gone. - Setting up log_file_handler is sufficiently covered by the one in the pytest_runtestloop hook, since these hooks don't have access to the caplog fixture. - The `log_cli_handler.set_when` can move inline.

bluetech · 2020-05-12T22:50:26Z

I fixed the test failure, and now it's also faster than the previous version (updated PR description), so it's ready for review.

Zac-HD

Very nice! Performance optimisations often involve less readable code, but this reads like a pleasant refactoring that happens to make things faster too 👍

testing/logging/test_fixture.py

twmr

Great job @bluetech. The usage of nested context managers were one of things that I really disliked when I integrated the plugin into pytest-dev/pytest. You have improved this a lot, thx!

twmr · 2020-05-15T20:12:42Z

src/_pytest/logging.py

+            log_handler.reset()
+            item._store[catch_log_handler_key] = log_handler
+            item._store[catch_log_records_key][when] = log_handler.records
+
            if self.log_file_handler is not None:
                with catching_logs(self.log_file_handler, level=self.log_file_level):
                    yield
            else:
                yield


@bluetech I like the usage of yield-from in this PR! WDYT about converting this if self.log_file_handler block (and also the block in pytest_collection) also into a generator from which you yield? Unfortunately I can't come up with a good name for this generator. What about yield from self.forward_logs_to_logfile()?

I think we can make it mostly go away! But if not, I'll try your suggestion.

twmr · 2020-05-15T20:20:09Z

src/_pytest/logging.py

            if self.print_logs:
                # Add a captured log section to the report.
                log = log_handler.stream.getvalue().strip()
                item.add_report_section(when, "log", log)

    @pytest.hookimpl(hookwrapper=True)
    def pytest_runtest_setup(self, item):
-        with self._runtest_for(item, "setup"):
-            yield
+        empty = {}  # type: Dict[str, List[logging.LogRecord]]


Maybe you can split up the type definiton of catch_log_records_key into two:

catch_log_records_map

catch_log_records_key

where the latter is defined as Store[catch_log_records_key]. Thus you can use empty = {} # type catch_log_records_map, here. TBH I don't know if this really works

These I think will also go away eventually. They are used for the plugin<->fixture interaction, but I think we should refactor this to be more like what the capture plugin does (for #7162).

bluetech · 2020-05-17T14:22:30Z

Thanks for the reviews @Zac-HD and @thisch!

Upon looking at logging a bit more, and looking at the open issues/PRs, I think that the main change here ("reuse LoggingCaptureHandler") might have some interactions with them, so I decided to defer it for a bit. Instead, I took the other changes from here (and some additional ones) into a new PR #7224. Once/if it's merged, I will submit a few more changes that I have in mind (probably including the reuse optimization, and some changes to the fixture-plugin interaction).

Zac-HD · 2020-05-17T14:29:09Z

Thanks @bluetech - I really appreciate the care you're putting into this, from design to code to PR writeups 😍

Please @-mention me in the new PR once tests are passing and I'll give it a priority review!

bluetech marked this pull request as draft May 12, 2020 15:19

bluetech force-pushed the logging-reuse-capture-handler branch from 363db7e to 895a7f8 Compare May 12, 2020 22:27

bluetech added 5 commits May 13, 2020 01:29

logging: use item's store for private attributes

942b737

This makes things type-safe.

logging: inline _runtest_for_main into _runtest_for

d34d7b7

This avoids a little bit of overhead, and makes the code a bit clearer too.

logging: yield from _runtest_for instead of contextmanager

2a4d8bf

Avoid the slight overhead of contextmanager.

bluetech force-pushed the logging-reuse-capture-handler branch from 895a7f8 to 4c2004a Compare May 12, 2020 22:29

logging: log hooks no longer need to be hookwrappers

4658296

bluetech marked this pull request as ready for review May 12, 2020 22:49

Zac-HD approved these changes May 13, 2020

View reviewed changes

testing/logging/test_fixture.py Show resolved Hide resolved

Zac-HD added plugin: logging related to the logging builtin plugin type: performance performance or memory problem/improvement labels May 13, 2020

twmr approved these changes May 15, 2020

View reviewed changes

bluetech closed this May 17, 2020

bluetech mentioned this pull request May 18, 2020

logging: reuse LoggingCaptureHandler instance since it's expensive to create #7227

Merged

bluetech deleted the logging-reuse-capture-handler branch July 14, 2020 07:20

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logging: some optimizations #7214

logging: some optimizations #7214

bluetech commented May 12, 2020 •

edited

bluetech commented May 12, 2020

bluetech commented May 12, 2020

Zac-HD left a comment

twmr left a comment

twmr May 15, 2020

bluetech May 17, 2020

twmr May 15, 2020

bluetech May 17, 2020

bluetech commented May 17, 2020

Zac-HD commented May 17, 2020

logging: some optimizations #7214

logging: some optimizations #7214

Conversation

bluetech commented May 12, 2020 • edited

bluetech commented May 12, 2020

bluetech commented May 12, 2020

Zac-HD left a comment

Choose a reason for hiding this comment

twmr left a comment

Choose a reason for hiding this comment

twmr May 15, 2020

Choose a reason for hiding this comment

bluetech May 17, 2020

Choose a reason for hiding this comment

twmr May 15, 2020

Choose a reason for hiding this comment

bluetech May 17, 2020

Choose a reason for hiding this comment

bluetech commented May 17, 2020

Zac-HD commented May 17, 2020

bluetech commented May 12, 2020 •

edited