Improve watch performance by using stable identities for Snapshot iterables

[gluxon]

A large monorepo my team works on is seeing an issue where Webpack rebuilds report as finished, but webpack-dev-server doesn't respond until a minute later.

Summary

Starting with performance changes up front. (See below for a description of what we were seeing.) Here's the LazySet merge performance for compilation.fileDependencies in this monorepo before/after:

	merge Loop Iterations	Timing(ms)
Before	1,198,677	23,045.10
After	464,918	1,726.25

These aren't scientific timings ran over multiple trials. I can perform that if needed.

Investigation

CPU Profiling

Running the build in a CPU profiler revealed a large amount of time spent calling watchpack's watch function. This is after the initial Webpack build. The white space in the profile below is in between the initial build, and saving a file in the repo that has just been modified.

webpack/lib/Watching.js

Lines 303 to 307 in e2f1592

	this.watch(
	compilation.fileDependencies,
	compilation.contextDependencies,
	compilation.missingDependencies
	);

Going down the call stack, it looks like watchpack iterates over compilation.fileDependencies, triggering LazySet's merge function.

webpack/lib/util/LazySet.js

Lines 16 to 22 in 93ce24d

	const merge = (targetSet, toMerge) => {
	for (const set of toMerge) {
	for (const item of set) {
	targetSet.add(item);
	}
	}
	};

I patched the merge function to output how many items were being iterated over and their time.

const { performance } = require("perf_hooks");
const merge = (targetSet, toMerge) => {
    let count = 0;
    const before = performance.now();
    for (const set of toMerge) {
        for (const item of set) {
            targetSet.add(item);
            count++
        }
    }
    if (count > 5000) {
        const duration = performance.now() - before;
        console.log(`Items iterated during merge: ${count}, ${duration} ms`)
    }
};

The results:

Items iterated during merge: 1198677, 23045.103875994682 ms
Items iterated during merge: 726370, 8386.988652005792 ms

The 1st set iterated corresponds to compilation.fileDependencies.

LazySet toMerge Duplicates

Inspecting compilation.fileDependencies in an interactive debugger shows that this LazySet has a lot of duplicates in its toMerge field.

Adding a breakpoint to the merge function commented on above and inspecting the toMerge argument:

❯ toMerge.size
128116
❯ new Set([...toMerge].map(snapshotIterable => snapshotIterable.snapshot)).size
62175

This is after LazySet._toMerge has had its contents moved from LazySet._toDeepMerge. Attaching a screenshot of the call stack in VS Code's debugger if that helps.

---

What kind of change does this PR introduce?

One of the reasons _toMerge gets so large is because every SnapshotIterable is uniquely constructed, even if they're derived from the same underlying Snapshot class.

This PR gives snapshot iterables stable identifiers, which reduces the items in the _toMerge set and significantly improved performance in this app.

After this change, the log output from above becomes:

Items iterated during merge: 464918, 1726.2539209723473 ms
Items iterated during merge: 561334, 222.49260300397873 ms

Did you add tests for your changes?

I added tests to ensure the snapshot iterables returned are stable across multiple calls, but the tests could probably be written better. I'd appreciate a gut check from the Webpack team that this change makes sense before improving tests more.

Does this PR introduce a breaking change?

It does not.

What needs to be documented once your changes are merged?

Questions for Reviewers

Thanks for looking at this!

• Does this change make sense, or should I investigate improving performance of this watch call in a different way?
• Would it make sense to use WeakRef to prevent these saved iterable objects from living longer than necessary? I think we'd have to check for the API's existence and gracefully fallback to support older Node.js versions.

fixes #15231

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: gluxon / name: Brandon Cheng (8e56d7f, ff6f776)

[webpack-bot]

For maintainers only:

• This needs to be documented (issue in webpack/webpack.js.org will be filed when merged)
• This needs to be backported to webpack 4 (issue will be created when merged)

[gluxon]

Opening as ready for review to get initial feedback. 🙂 I contacted my company's CLA management team to work out the EasyCLA.

[JoostK]

I believe I saw the same bottleneck before, then reported as #15231.

[gluxon]

@JoostK Thanks for linking that. I was curious if others had seen this issue. I would be interested to know if the patch here alleviates the problem for your team if you have a moment to manually apply and test.

While this PR brought our team's merge time down from 1 minute, I did notice times still vary from 1s to 4s. I think Snapshot can non-deterministically end up in a deeply nested state that takes SnapshotIterator a bit of time to flatten. I was hoping to continue investigating there, but I'm not sure if it's worthwhile yet unless it would help others.

[JoostK]

I just checked with this patch applied and it didn't seem any faster. I haven't taken measurements but it doesn't seem like it resolves #15231.

[gluxon]

Got it. I'd wager there's more work needed here too. The next step I was thinking of was attempting to serialize the Snapshot tree and comparing it between the fast ~1s merge case and slow ~4s case.

As a heads up, the watch -> merge slowness this PR addresses can be difficult to perceive without measuring/profiling. The watch call happens after Webpack says it's ready/done, so the timings here aren't typically printed on the console. If you have time, I would be curious if the lib/Watching.js timings are different in @mattlewis92's profiling here: #15231 (comment)

[sokra]

• Does this change make sense, or should I investigate improving performance of this watch call in a different way?

Makes sense to me

• Would it make sense to use WeakRef to prevent these saved iterable objects from living longer than necessary? I think we'd have to check for the API's existence and gracefully fallback to support older Node.js versions.

I don't think that makes sense, since each iterator only keeps a referenced to the Snapshot, so it doesn't add any large memory overhead. Actually it reduces memory since only a single iterator is created per Snapshot.

Items iterated during merge: 1198677, 23045.103875994682 ms

Items iterated during merge: 464918, 1726.2539209723473 ms

It's interesting that reducing the count by 50% improves performance by 13x. Why is that? Maybe the SnapshotIterables are far more expensive than the remaining Iterables during merge, and the number of SnapshotIterables was also reduced by ~13x.

I think Snapshot can non-deterministically end up in a deeply nested state

The way Snapshots are optimized is really non-deterministic, since it depends a lot on the order and speed in creating them (which depends on fs operations).

I contacted my company's CLA management team to work out the EasyCLA.

👍

The PR looks good and I'll merge it afterwards

[gluxon]

I don't think that makes sense, since each iterator only keeps a referenced to the Snapshot, so it doesn't add any large memory overhead. Actually it reduces memory since only a single iterator is created per Snapshot.

Nice. Glad to have a second pair of eyes to confirm that.

It's interesting that reducing the count by 50% improves performance by 13x. Why is that? Maybe the SnapshotIterables are far more expensive than the remaining Iterables during merge, and the number of SnapshotIterables was also reduced by ~13x.

I was surprised by this too and came to the same conclusion as you. I think the SnapshotIterable objects that were duplicated were typically more nested/larger than the more unique objects.

I hadn't thought of this until your memory comment, but I'd expect garbage collection of SnapshotIterable objects to happen less in this watch -> merge call now. There may have been performance improvements from just not running GC as frequently.

The way Snapshots are optimized is really non-deterministic, since it depends a lot on the order and speed in creating them (which depends on fs operations).

👍 Thanks for confirming that. That's nice to know.

[webpack-bot]

@gluxon Thanks for your update.

I labeled the Pull Request so reviewers will review it again.

@sokra Please review the new changes.

[gluxon]

EasyCLA should be good now. I force pushed a rebase without any changes. Thanks again for review @sokra.

[gluxon]

Are the codecov status errors something that's been seen before in the Webpack repo?

It is possible that the changes here affected code paths in tests, but wanted to check if this was seen before investigating how my changes would have affected logic in lib/Compiler.js and lib/Compilation.js.

[alexander-akait]

@gluxon Ignore it, it is normal for big changes, especial for 0.01 😄

[gluxon]

Understood. Thanks! 😄

[sokra]

Thanks

[gluxon]

Thanks for the reviews and fast turnaround time! Hope this helps Webpack's users. 🤞