perf: do not compute log message until required #5410
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
…eeded The idea is that sometimes we do heavy operations for silly logs, but we then discard just the log output. Instead, we can pass a callback and if the log is never needed for display, it won't actually call the heavy operations.
There might be multiple loggers resolving the message eventually. Wrap it in `memoize` so that it only gets resolved once.
TimBeyer
force-pushed
the
perf/deferred-logging
branch
from
19c17ed
to
2e3473c
Compare
TimBeyer
changed the title
stefreak
reviewed
Nov 16, 2023
| @@ -318,38 +340,38 @@ export abstract class Log<C extends BaseContext = LogContext> implements LogConf | |||
| /** | |||
| * Render a log entry at the silly level. This is the highest verbosity. | |||
| */ | |||
| silly(params: string | LogParams) { | |||
| silly(params: Msg | LogParams) { | |||
There was a problem hiding this comment.
I think we might want to enforce using the closure instead of a string for silly
stefreak
approved these changes
Nov 16, 2023
TimBeyer
commented
Nov 16, 2023
| @@ -406,28 +406,28 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> { | |||
|
|
|||
| if (status?.aborted || status?.error) { | |||
| // Status is either aborted or failed | |||
| this.log.silly(`Request ${request.getKey()} status: ${resultToString(status)}`) | |||
| this.log.silly(() => `Request ${request.getKey()} status: ${resultToString(status)}`) | |||
There was a problem hiding this comment.
For for the record, these resultToString calls were the main culprits of the time spent in logging by using CircularJSON.stringify.
github-merge-queue
bot
removed this pull request from the merge queue due to failed status checks
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
What this PR does / why we need it:
Before letting go of the whole performance epic, I did one last round of CPU profiling and noticed that for large projects we spend a large amount of time calling functions that are only used in higher log levels, which aren't actually really set most of the time. The problem is that we do the heavy processing for the log entries, but then we eventually discard them.
Thus I changed the logger so it can accept a callback, and if nothing logs it, the callback never gets called.
I don't want to spend large amounts of time on this anymore, and this was just a quick search and replace thing, so if it works let's consider merging it, if not, we can still keep this around as inspiration.
For now this was only applied to the
sillylog level since that's where the most expensive log lines were coming from.This improves performance of
garden validateon a project with 500 modules from ~32 to ~25 seconds.So this change gives an about 20% time saving for very large projects, which is pretty nice for such a simple change.
Which issue(s) this PR fixes:
Fixes #
Special notes for your reviewer: