Skip to content

TerminalWriter: write "collecting" msg only once every 0.5s #4225

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Oct 24, 2018
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions changelog/4225.feature.rst
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
Improve performance with collection reporting in non-quiet mode with terminals.

The "collecting …" message is only printed/updated every 0.5s.
15 changes: 13 additions & 2 deletions src/_pytest/terminal.py
Original file line number Diff line number Diff line change
Expand Up @@ -248,6 +248,7 @@ def __init__(self, config, file=None):
self.isatty = file.isatty()
self._progress_nodeids_reported = set()
self._show_progress_info = self._determine_show_progress_info()
self._collect_report_last_write = None

def _determine_show_progress_info(self):
"""Return True if we should display progress information based on the current config"""
Expand Down Expand Up @@ -474,7 +475,11 @@ def _width_of_current_line(self):
return self._tw.chars_on_current_line

def pytest_collection(self):
if not self.isatty and self.config.option.verbose >= 1:
if self.isatty:
if self.config.option.verbose >= 0:
self.write("collecting ... ", bold=True)
self._collect_report_last_write = time.time()
elif self.config.option.verbose >= 1:
self.write("collecting ... ", bold=True)

def pytest_collectreport(self, report):
Expand All @@ -485,13 +490,19 @@ def pytest_collectreport(self, report):
items = [x for x in report.result if isinstance(x, pytest.Item)]
self._numcollected += len(items)
if self.isatty:
# self.write_fspath_result(report.nodeid, 'E')
self.report_collect()

def report_collect(self, final=False):
if self.config.option.verbose < 0:
return

if not final:
# Only write "collecting" report every 0.5s.
t = time.time()
if self._collect_report_last_write > t - 0.5:
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

for fluid ux appearance even with larger suites i propose lowering this to 0.1

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@RonnyPfannschmidt
It makes quite a difference in overall performance.
1.17s with -q
1.24s with 0.5s
2.26s with 0.1s

I think it is not worth 1s just for "fluid ux appearance", which only means having the number updated more often.

I suggest giving this a try yourself.
IMHO it is also better from an UX appearance to not have "much flickering", but some more calm feedback instead.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

now thats interesting

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks for the update, based on your research i would like to get into sorting out the internals later on

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah.. I've looked into this in more depth, and it appears to be basically the writing to sys.stdout (but I was unable to reproduce it with a simple script).
urxvt is faster than kitty for me, but it depends on the terminal width with urxvt more than with kitty.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is likely related to the corner case of writing a full line (with "\r" in front), possibly at the last line of the terminal - AFAIK the lower right column is a bit special often in terminal regards.

return
self._collect_report_last_write = t

errors = len(self.stats.get("error", []))
skipped = len(self.stats.get("skipped", []))
deselected = len(self.stats.get("deselected", []))
Expand Down