google / google/built_value.dart

Generator v8 is ~1.75x slower than v7 due to resource contention in build_resolvers

Open
#1,109 5 comments 1 reaction 0 assignees View on GitHub
Dominant language
Dart
Stars
886
Forks
195
Avg merge
1d 11h
Merged PRs (30d)
4

Description

I'm not sure yet where the real issue lies or what a fix might look like, but I decided to create the issue for this repo because we've only been able to reproduce this regression when upgrading from built_value_generator v7 to v8 and with minimal other changes (in particular: **no change to the Dart version, the `analyzer` version, or versions of any `build_*` package**).

source_gen-based builders like this one are the most significant contributors to iterative build times, so in one of our larger projects, we measure the time it takes to generate those source_gen-based assets via a `build_runner build` command with a build filter that ensures that only the source_gen-based outputs are requested. As we were upgrading from v7 to v8, we noticed a significant regression in the two largest packages:

| Dart SDK | built_value_generator | Duration |
|----------|-----------------------|----------|
| 2.13.4 | v7.1.1 | ~25s |
| 2.13.4 | v8.0.4 | ~44s |

This is particularly interesting because the obvious culprits like the SDK, `pkg:analyzer`, or `pkg:build_*` do not change. Additionally, due to a backpatch to v7.1.1, the implementation of the generator in built_value_generator is very similar:

**V7**
```dart
class BuiltValueGenerator extends Generator {
// Allow creating via `const` as well as enforces immutability here.
const BuiltValueGenerator();

@override
Future generate(LibraryReader library, BuildStep buildStep) async {
// Workaround for https://github.com/google/built_value.dart/issues/941.
LibraryElement libraryElement;
var attempts = 0;
while (true) {
try {
libraryElement = await buildStep.resolver.libraryFor(
await buildStep.resolver.assetIdForElement(library.element));
libraryElement.session.getParsedLibraryByElement(libraryElement);
break;
} catch (_) {
++attempts;
if (attempts == 10) {
log.severe('Analysis session did not stabilize after ten tries!');
return null;
}
}
}

var result = StringBuffer();

try {
final enumCode = EnumSourceLibrary(libraryElement).generateCode();
if (enumCode != null) result.writeln(enumCode);
final serializerSourceLibrary = SerializerSourceLibrary(libraryElement);
if (serializerSourceLibrary.needsBuiltJson ||
serializerSourceLibrary.hasSerializers) {
result.writeln(serializerSourceLibrary.generateCode());
}
} on InvalidGenerationSourceError catch (e, st) {
result.writeln(_error(e.message));
log.severe(
'Error in BuiltValueGenerator for '
'${libraryElement.source.fullName}.',
e,
st);
} catch (e, st) {
result.writeln(_error(e.toString()));
log.severe(
'Unknown error in BuiltValueGenerator for '
'${libraryElement.source.fullName}.',
e,
st);
}

for (var element in libraryElement.units.expand((unit) => unit.types)) {
if (ValueSourceClass.needsBuiltValue(element)) {
try {
result.writeln(ValueSourceClass(element).generateCode() ?? '');
} catch (e, st) {
result.writeln(_error(e));
log.severe('Error in BuiltValueGenerator for $element.', e, st);
}
}
}

if (result.isNotEmpty) {
return '$result'
'\n'
'// ignore_for_file: '
'always_put_control_body_on_new_line,'
'always_specify_types,'
'annotate_overrides,'
'avoid_annotating_with_dynamic,'
'avoid_as,'
'avoid_catches_without_on_clauses,'
'avoid_returning_this,'
'lines_longer_than_80_chars,'
'omit_local_variable_types,'
'prefer_expression_function_bodies,'
'sort_constructors_first,'
'test_types_in_equals,'
'unnecessary_const,'
'unnecessary_new';
} else {
return null;
}
}
}
```

**V8**
```dart
class BuiltValueGenerator extends Generator {
// Allow creating via `const` as well as enforces immutability here.
const BuiltValueGenerator();

@override
Future generate(LibraryReader library, BuildStep buildStep) async {
// Workaround for https://github.com/google/built_value.dart/issues/941.
LibraryElement libraryElement;
var attempts = 0;
while (true) {
try {
libraryElement = await buildStep.resolver.libraryFor(
await buildStep.resolver.assetIdForElement(library.element));
libraryElement.session.getParsedLibraryByElement(libraryElement);
break;
} catch (_) {
++attempts;
if (attempts == 10) {
log.severe('Analysis session did not stabilize after ten tries!');
return null;
}
}
}

var result = StringBuffer();
try {
final enumCode = EnumSourceLibrary(libraryElement).generateCode();
if (enumCode != null) result.writeln(enumCode);
final serializerSourceLibrary = SerializerSourceLibrary(libraryElement);
if (serializerSourceLibrary.needsBuiltJson ||
serializerSourceLibrary.hasSerializers) {
result.writeln(serializerSourceLibrary.generateCode());
}
} on InvalidGenerationSourceError catch (e, st) {
result.writeln(_error(e.message));
log.severe(
'Error in BuiltValueGenerator for '
'${libraryElement.source.fullName}.',
e,
st);
} catch (e, st) {
result.writeln(_error(e.toString()));
log.severe(
'Unknown error in BuiltValueGenerator for '
'${libraryElement.source.fullName}.',
e,
st);
}

for (var element in libraryElement.units.expand((unit) => unit.classes)) {
if (ValueSourceClass.needsBuiltValue(element)) {
try {
result.writeln(ValueSourceClass(element).generateCode() ?? '');
} catch (e, st) {
result.writeln(_error(e));
log.severe('Error in BuiltValueGenerator for $element.', e, st);
}
}
}

if (result.isNotEmpty) {
return '$result'
'\n'
'// ignore_for_file: '
'always_put_control_body_on_new_line,'
'always_specify_types,'
'annotate_overrides,'
'avoid_annotating_with_dynamic,'
'avoid_as,'
'avoid_catches_without_on_clauses,'
'avoid_returning_this,'
'deprecated_member_use_from_same_package,'
'lines_longer_than_80_chars,'
'omit_local_variable_types,'
'prefer_expression_function_bodies,'
'sort_constructors_first,'
'test_types_in_equals,'
'unnecessary_const,'
'unnecessary_new';
} else {
return null;
}
}
}
```

And after doing some profiling, we determined that almost all of the time spent by this generator occurred within this call:

```
libraryElement = await buildStep.resolver.libraryFor(
await buildStep.resolver.assetIdForElement(library.element));
```

Again, it's worth noting that neither any `build_*` packages nor the `analyzer` package change, yet this call still produces a build regression between v7 and v8.

When digging into this code path, I noticed that the build_resolvers package uses a resource pool with only a single available resource to avoid race conditions:
https://github.com/dart-lang/build/blob/build_resolvers-v1.5.3/build_resolvers/lib/src/resolver.dart#L115-L131

That seemed like it could be inefficient if something caused a lot more requests to the resolver at the same time, so I added some timing logs to capture how long each request took to resolve and how long each request waited for a resource from that pool, as well as the total number of calls to that `_resolveIfNecessary()` function:

| Dart SDK | built_value_generator | Total time resolving | Total time waiting | Total # of requests |
|----------|-----------------------|---------------------|-------------------|-------------------|
| 2.13.4 | v7 | 6.08s | 39.09s | 22 |
| 2.13.4 | v8 | 6.33s | 61.28s | 22 |

So here we can see the build time regression, and it is almost entirely attributable to the time spent waiting rather than the time spent resolving. Additionally, the number of calls to resolve an asset are the same, so something else must be causing the slowdown/contention.

At this point I verified that in both cases, we're using v1.5.0 of `pkg:pool`, so it seems unlikely that the implementation of that resource pool is at fault.

Thinking that this could have been a bug that has since been fixed, I created a smaller repro that just uses built_value_generator and a few large files, and the build regression is introduced with built_value_generator v8 and never improves even on Dart SDK 2.14, 2.15, or 2.16, nor with analyzer v1, v2, or v3.

---

Unfortunately, I'm out of ideas. I realize I haven't been able to identify anything in this repo as a cause, but we _are_ seeing this slowdown specifically when upgrading from v7 to v8. I'm hoping that maybe we can loop in the pkg:build maintainers to see if anyone has an idea for what to check next.

@davidmorgan @jakemac53 @natebosch

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.