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

[evanweible-wf]

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_valuegenerator 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

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

  @override
  Future<String> 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

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

  @override
  Future<String> 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

[jakemac53]

Did something change with respect to the dependencies of whatever the public import is? The resolver resolves all transitive imports of the library, so if the library which exposes the annotations got larger, that could increase analysis time?

[jakemac53]

An import to package:meta was added - there were no imports before. It seems unlikely it could cause such a large change, but maybe try restricting built_value to <=8.0.6 to see how that affects things?

[dave26199]

Thanks for all the analysis :)

Is your code null safe? The big change in the generator for v7->v8 is that v8 will output null safe code if the target library is null safe.

I seem to remember there were changes to the analyzer apis it uses at the same time, maybe something there causes the resolution to be slower by causing the analyzer to do more work each time.

[evanweible-wf]

maybe try restricting built_value to <=8.0.6 to see how that affects things?

I had tried pinning to built_value 8.0.0 and built_collection 5.0.0 before and still saw the same build regression, but I tried this again yesterday and all of the sudden the time spent waiting went back to what we were seeing on v7, but the total time spent building our source_gen assets was still just as slow. Maybe the buildresolvers theory was a red herring and the slowdown just happens to be measurable at that code path randomly ¯_(ツ)/¯

Anyway, I measured everything again this morning and tried to be more consistent. Each measurement takes these steps:

1. Delete .dart_tool/
2. dart pub get
3. Run dart run build_runner build --delete-conflicting-outputs --build-filter="imaginary.dart" >/dev/null to get some of the initial build_runner work out of the way without actually running built_value_generator
4. Run time dart run build_runner build --delete-conflicting-outputs --build-filter="**.sg.g.dart" to get the total source_gen build time. Note: we use a .sg.dart naming convention for files that need to be built by source_gen-based builders so we can narrow the inputs for those builders in our build.yaml
5. Parse the logs from that build which include additional timing logs from a local copy of build_resolvers to get the time spent resolving and time spent waiting for the resource pool.

built_value	built_collection	built_value_generator	Total build time	Time resolving	Time waiting	Total # of requests
7.x	4.x	7.x.	39s	1.7s	25.4s	22
8.0.0	5.0.0	8.0.4	66s	1.7s	25.9s	22
8.1.4	5.1.1	8.0.4	67s	2.0s	24.4s	22

So as you can see, we're still seeing a significant slowdown in the build command, but it looks like it's not necessarily attributable to build_resolvers. I'm going to walk back up that stack and add some similar timing logs to see if I can get any more info.

---

Is your code null safe? The big change in the generator for v7->v8 is that v8 will output null safe code if the target library is null safe.

I had this thought, as well. In my repro, I copied over some of the files that we run built_value_generator on and measured as-is (pre-null-safe) and then after converting that code to null-safety and saw no change. I also tried writing a simple generator that makes the same calls to buildStep.resolver that built_value_generator does and measured with that builder code being pre-null-safe and null-safe and saw no difference.

[evanweible-wf]

^ I'm doubting my memory on the test builder I wrote when I was trying to determine whether the builder being null-safe causes this.. I'll try to verify whether I actually saw the same slowdown with that builder. If not, maybe something the v8 generator is doing to support both pre-null-safe and null-safe code is causing this.