Log performance improvement (#23925)

* util.tty.log: read up to 100 lines if ready

Rework to read up to 100 lines from the captured stdin as long as data
is ready to be read immediately.  Adds a helper function to poll with
`select` for ready data.  This showed a roughly 5-10x perf improvement
for high-rate writes through the logger with relatively short lines.

* util.tty.log: Defer flushes to end of ready reads

Rather than flush per line, flush per set of reads.  Since this is a
non-blocking loop, the total perceived wait is short.

* util.tty.log: only scan each line once, usually

Rather than always find all control characters then substitute them all,
use `subn` to count the number of control characters replaced.  Only if
control characters exist find out what they are.  This could be made
truly single pass with sub with a function, but it's a more intrusive
change and this got 99%ish of the performance improvement (roughly
another 2x in some cases).

* util.tty.log: remove check for `readable`

Python < 3 does not support a readable check on streams, should not be
necessary here since we control the only use and it's explicitly a
stream to be read.
This commit is contained in:
Tom Scogland 2021-05-31 20:33:14 -07:00 committed by GitHub
parent ea4a2c9120
commit 4a7b0afde2
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23

View file

@ -771,29 +771,40 @@ def _writer_daemon(stdin_multiprocess_fd, read_multiprocess_fd, write_fd, echo,
raise raise
if in_pipe in rlist: if in_pipe in rlist:
line_count = 0
try:
while line_count < 100:
# Handle output from the calling process. # Handle output from the calling process.
line = _retry(in_pipe.readline)() line = _retry(in_pipe.readline)()
if not line: if not line:
break return
line_count += 1
# find control characters and strip them. # find control characters and strip them.
controls = control.findall(line) clean_line, num_controls = control.subn('', line)
line = control.sub('', line)
# Echo to stdout if requested or forced. # Echo to stdout if requested or forced.
if echo or force_echo: if echo or force_echo:
sys.stdout.write(line) sys.stdout.write(clean_line)
sys.stdout.flush()
# Stripped output to log file. # Stripped output to log file.
log_file.write(_strip(line)) log_file.write(_strip(clean_line))
log_file.flush()
if num_controls > 0:
controls = control.findall(line)
if xon in controls: if xon in controls:
force_echo = True force_echo = True
if xoff in controls: if xoff in controls:
force_echo = False force_echo = False
if not _input_available(in_pipe):
break
finally:
if line_count > 0:
if echo or force_echo:
sys.stdout.flush()
log_file.flush()
except BaseException: except BaseException:
tty.error("Exception occurred in writer daemon!") tty.error("Exception occurred in writer daemon!")
traceback.print_exc() traceback.print_exc()
@ -844,3 +855,7 @@ def wrapped(*args, **kwargs):
continue continue
raise raise
return wrapped return wrapped
def _input_available(f):
return f in select.select([f], [], [], 0)[0]