Skip to content

Defer log record formatting until after filters#4954

Open
happz wants to merge 1 commit into
mainfrom
log-defer-formating
Open

Defer log record formatting until after filters#4954
happz wants to merge 1 commit into
mainfrom
log-defer-formating

Conversation

@happz
Copy link
Copy Markdown
Contributor

@happz happz commented Jun 2, 2026

Logger._log formatted the message - tmt run does not care, whatever is logged is also emitted and lands in log.txt, but there are commands that do not have log.txt, like tmt * ls, that do not have log file. Such commands could benefit from rendering of messages that would be actually emitted.

It turns out LogRecordDetails already contains everything we need to format the message. If the log record has details, we can easily postpone formatting.

Brief comparison of tmt test ls in tmt repo, on my workstation:

  • before: 10 seconds (no prof), 25 seconds (with prof), 17/16/8 seconds in debug/_log/indent;
  • after: 7 seconds (no prof), 17 seconds (with prof), 7/7 seconds in debug/_log, indent does not register.

Simple tmt in a repo with 179 plans takes 11 seconds before the change, 9 seconds after. In a repo with 3679 tests & 1 plan, 2 minutes 28 seconds before, 1 minute 33 seconds after.

The effect is measurable, reliably, running with profiler makes it stand out even more, yet it's not as big as expected.

PR addresses just one part of the formatting process, i.e. rendering of a message by logging subsystem from key and optional value fields, and its indentation. It does not address messages that are actually formatted in place, as f-strings, and never emitted. To address these, more work will be needed, as the next iteration on top of this PR.

Pull Request Checklist

  • implement the feature
  • write the documentation
  • extend the test coverage
  • update the specification
  • adjust plugin docstring
  • modify the json schema
  • mention the version
  • include a release note

`Logger._log` formatted the message - `tmt run` does not care, whatever
is logged is also emitted and lands in `log.txt`, but there are commands
that do not have `log.txt`, like `tmt * ls`, that do not have log file.
Such commands could benefit from rendering of messages that would be
actually emitted.

It turns out `LogRecordDetails` already contains everything we need to
format the message. If the log record has `details`, we can easily
postpone formatting.

Brief comparison of `tmt test ls` in tmt repo, on my workstation:

- before: 10 seconds (no prof), 25 seconds (with prof), 17/16/8 seconds
  in `debug`/`_log`/`indent`;
- after:  7 seconds (no prof), 17 seconds (with prof), 7/7 seconds in
  `debug`/`_log`, `indent` does not register.

Simple `tmt` in a repo with 179 plans takes 11 seconds before the
change, 9 seconds after. The effect is measurable, reliably, running
with profiler makes it stand out even more, yet it's not as big as
expected.
@happz happz added code | logging Changes related to debug logging ci | full test Pull request is ready for the full test execution labels Jun 2, 2026
Copy link
Copy Markdown
Contributor

@gemini-code-assist gemini-code-assist Bot left a comment

Choose a reason for hiding this comment

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

Code Review

This pull request introduces a custom LogRecord class and a type guard to handle custom log record details, refactoring formatting and filtering logic to use this custom record type. Feedback suggests chaining the log record factory instead of overriding it directly to preserve existing custom factories set by other libraries or test runners.

Important

The consumer version of Gemini Code Assist on GitHub is being sunset. Starting June 18, 2026, new organization installations will be blocked, and all code review activity will officially cease on July 17, 2026.
For more details on the timeline and next steps, please review the Help Documentation.

Comment thread tmt/log.py
Comment on lines +349 to +350
# Tell logging to use our custom log record class.
logging.setLogRecordFactory(LogRecord)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

high

Chain the log record factory to preserve any existing custom factories set by other libraries or test runners. Overriding it directly can break logging capture or custom record types.

# Tell logging to use our custom log record class, preserving any existing factory.
_old_factory = logging.getLogRecordFactory()


def _log_record_factory(*args: Any, **kwargs: Any) -> logging.LogRecord:
    record = _old_factory(*args, **kwargs)
    if not isinstance(record, LogRecord):
        record.__class__ = LogRecord
    return record


logging.setLogRecordFactory(_log_record_factory)

@github-project-automation github-project-automation Bot moved this to backlog in planning Jun 3, 2026
@AthreyVinay AthreyVinay moved this from backlog to implement in planning Jun 3, 2026
@happz happz moved this from implement to review in planning Jun 3, 2026
@happz happz marked this pull request as ready for review June 3, 2026 20:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ci | full test Pull request is ready for the full test execution code | logging Changes related to debug logging

Projects

Status: review

Development

Successfully merging this pull request may close these issues.

2 participants