The only real difference I am aware of is around the migration from.packages files to package_config.json files. This does introduce language versioning and the parsing of that file is also more complex... but I doubt the actual parsing is the problem.

I would have actually expected it to be a bit faster because we used to recreate the .packages file for each action 😭 .

So, to me that indicates it is likely that the kernel compilation itself got somewhat slower...

jakemac53 on 7 May 2020

For dart2js, I would start by comparing the output from adding -v to the command line for both cases.
@robbecker-wf has send us these before.

rakudrama on 7 May 2020

Okay I can work on getting those. Given what @jakemac53 said, should this issue be moved to dart-lang/sdk or is it fine here?

evanweible-wf on 7 May 2020

We can leave it here for now, its going to take some investigation to confirm where the slowdown is coming from.

jakemac53 on 7 May 2020

👍1

Here's the dart2js verbose output from our main application. Used a diff view here - red lines indicate a negative change (more/slower), green lines indicate an improvement.

```diff

Info: Compiling file:///Users/robbecker/code/wdesk/build/web/main.dart (2.8.1)

Info: Kernel load complete
Info: Resolved 338604 elements.
Info: All native types marked as used due to ResolutionWorldImpactBuilder(k:method(callMethod))member: k:method(callMethod)
static uses:
StaticUse(k:method(JS),StaticUseKind.STATIC_INVOKE,null,[dynamic],CallStructure(arity=6, types=1))
type uses:
TypeUse(String,TypeUseKind.PARAMETER_CHECK)
TypeUse(List,TypeUseKind.PARAMETER_CHECK)
const-literals:
Object|Null

[#].apply(#, #)

native-data:
NativeBehavior(returns: [Object, Null], creates: [Object, Null], sideEffects: SideEffects(reads anything; writes anything), throws: may).

Info: Resolved 1012 native elements used, 0 native elements dead.
Info: Performing global type inference
Info: Added 332531 elements in inferencing graph.
Info: Inferred 8190891 types.
Info: Compiling methods
Info: Compiled 296087 methods.
Info: Compiled 1012 native classes, 0 native classes omitted.
Info: Emitting JavaScript
Info: Timings:
kernel loader: 131.071s (13.0%)
Front end: 17.854s (1.8%)
Front end > closures: 3.274s (0.3%)
Front end > worldImpact: 11.422s (1.1%)
Type inference: 377.334s (37.3%)
Deferred Loading: 19.226s (1.9%)
Deferred Loading > prepare: 0.045s (0.0%)
Deferred Loading > find-imports: 4.177s (0.4%)
Enqueue: 60.972s (6.0%)
Enqueue > resolution.staticUse: 1.568s (0.2%)
Enqueue > resolution.typeUse: 27.977s (2.8%)
Enqueue > resolution.dynamicUse: 18.021s (1.8%)
Enqueue > codegen.typeUse: 4.496s (0.4%)
Enqueue > codegen.staticUse: 6.099s (0.6%)
Enqueue > codegen.dynamicUse: 1.515s (0.1%)
Enqueue > codegen.constantUse: 1.293s (0.1%)
self: 46.372s (4.6%)
*self > impl.run: 0.012s (0.0%)
self > run: 3.374s (0.3%)
self > compileFromKernel: 0.273s (0.0%)
self > computeClosedWorld: 20.627s (2.0%)
self > processQueue: 0.164s (0.0%)
self > emptyQueue: 1.529s (0.2%)
self > applyImpact: 8.254s (0.8%)
self > work.run: 12.136s (1.2%)
SSA builder: 113.043s (11.2%)
SSA optimizer: 88.256s (8.7%)
SSA optimizer > SsaInstructionSimplifier: 25.538s (2.5%)
SSA optimizer > SsaTypeconversionInserter: 1.665s (0.2%)
SSA optimizer > SsaRedundantPhiEliminator: 0.476s (0.0%)
SSA optimizer > SsaDeadPhiEliminator: 0.623s (0.1%)
SSA optimizer > SsaTypePropagator: 27.002s (2.7%)
SSA optimizer > SsaCheckInserter: 1.515s (0.1%)
SSA optimizer > SsaDeadCodeEliminator: 2.625s (0.3%)
SSA optimizer > SsaGlobalValueNumberer: 2.959s (0.3%)
SSA optimizer > SsaCodeMotion: 0.819s (0.1%)
SSA optimizer > SsaLoadElimination: 7.096s (0.7%)
SSA optimizer > SSA value range builder: 2.468s (0.2%)
SSA optimizer > SsaSimplifyInterceptors: 7.771s (0.8%)
SSA code generator: 33.257s (3.3%)
SSA code generator > SsaInstructionSelection: 1.329s (0.1%)
SSA code generator > SsaTypeKnownRemover: 0.595s (0.1%)
SSA code generator > SsaTrustedCheckRemover: 0.155s (0.0%)
SSA code generator > SsaAssignmentChaining: 0.627s (0.1%)
SSA code generator > SsaInstructionMerger: 2.111s (0.2%)
SSA code generator > SsaConditionMerger: 0.369s (0.0%)
SSA code generator > SsaShareRegionConstants: 0.548s (0.1%)
SSA code generator > SsaLiveIntervalBuilder: 4.480s (0.4%)
SSA code generator > SsaVariableAllocator: 6.953s (0.7%)
Code emitter: 116.160s (11.5%)
Code emitter > finalize rti: 11.472s (1.1%)
Code emitter > build program: 32.162s (3.2%)
Code emitter > emit program: 11.318s (1.1%)
Code emitter > write fragments: 45.356s (4.5%)
Code emitter > source-maps: 12.711s (1.3%)
Code emitter > emit buffers: 3.120s (0.3%)
Diagnostic handler: 0.034s (0.0%)
Total compile-time 1011.403s; setup 0.000s; async 0.091s; unaccounted 7.725s (0.76%)
Compiled 148,512,881 characters Dart to 39,571,365 characters JavaScript in 1013 seconds
Info: 18,603,357 characters JavaScript in main.dart.js
Dart file main.dart compiled to JavaScript: main.dart.js
Emitted file 329 JavaScript files.
Printing metrics for main
heap.old.used 12.116 GB (13009272400 B)
heap.old.used.max 10.984 GB (11794349888 B)
heap.old.capacity 13.263 GB (14240796672 B)
heap.old.capacity.max 13.263 GB (14240796672 B)
heap.old.external 32.000 B (32 B)
heap.new.used 10.008 MB (10494016 B)
heap.new.used.max 29.073 MB (30485312 B)
heap.new.capacity 32.000 MB (33554432 B)
heap.new.capacity.max 32.000 MB (33554432 B)
heap.new.external 0.000 B (0 B)
heap.global.used 12.126 GB (13019766416 B)
heap.global.used.max 12.617 GB (13547555808 B)
isolate.runnable.latency 80.483 ms (80483 us)
isolate.runnable.heap 0.000 B (0 B)

Printing metrics for vm-service
heap.old.used 4.513 MB (4732416 B)
heap.old.used.max 4.292 MB (4500864 B)
heap.old.capacity 5.129 MB (5378048 B)
heap.old.capacity.max 5.629 MB (5902336 B)
heap.old.external 0.000 B (0 B)
heap.new.used 512.000 kB (524288 B)
heap.new.used.max 0.000 B (0 B)
heap.new.capacity 2.000 MB (2097152 B)
heap.new.capacity.max 2.000 MB (2097152 B)
heap.new.external 48.000 B (48 B)
heap.global.used 5.013 MB (5256704 B)
heap.global.used.max 4.792 MB (5025152 B)
isolate.runnable.latency 4.773 ms (4773 us)
isolate.runnable.heap 0.000 B (0 B)

Printing metrics for VM
vm.isolate.count 1
vm.memory.current 47.605 MB (49917952 B)
vm.memory.max 9.064 GB (9732145152 B)

Printing metrics for vm-isolate
heap.old.used 95.781 kB (98080 B)
heap.old.used.max 0.000 B (0 B)
heap.old.capacity 1024.000 kB (1048576 B)
heap.old.capacity.max 1024.000 kB (1048576 B)
heap.old.external 0.000 B (0 B)
heap.new.used 0.000 B (0 B)
heap.new.used.max 0.000 B (0 B)
heap.new.capacity 0.000 B (0 B)
heap.new.capacity.max 0.000 B (0 B)
heap.new.external 0.000 B (0 B)
heap.global.used 95.781 kB (98080 B)
heap.global.used.max 0.000 B (0 B)
isolate.runnable.latency 0.000 us (0 us)
isolate.runnable.heap 0.000 B (0 B)

evanweible-wf on 7 May 2020

@jakemac53 is there a way I can get some debug output from the kernel compilation step when running a DDC build?

evanweible-wf on 7 May 2020

There is the --track-performance argument but we can't easily get fine grained info from inside the kernel step.

jakemac53 on 7 May 2020

@evanweible-wf Can you just give us the two outputs for dart2js? I'm not sure how to interpret the diff since it doesn't show both numbers for all phases.

rakudrama on 8 May 2020

@rakudrama sorry, I should have done that to start. I pushed up a few comparison builds to our CI builder to get more realistic numbers and it looks like the dart2js times are pretty similar between 2.7.2 and 2.8.1 (or 2.8.1 is slightly faster) for our main application. But local DDC builds are significantly slower, so I'm going to see what I can find with --track-performance and post here.

evanweible-wf on 8 May 2020

Here are some DDC numbers from the "also huge" package in question:

2.7.1

2.8.1

Each CollectDeps stage is significantly longer, even at the smaller compilation unit.
If there's a more helpful way to break this down, let me know.

I was the one who originally measured this package taking 6m to build using DDC when Evan wrote this issue. Today I've consistently seen that it's taking around 4m 15s (compared to ~2m 50s). I'm not sure why, though I only measured it once a couple days ago. I unfortunately don't have a record of which deps I used the first time.

smaifullerton-wk on 8 May 2020

^ did the same thing for a smaller library where the DDC build time increased from 1m 8s to 2m 17s

2.7.2
Screen Shot 2020-05-08 at 10 40 49 AM

2.8.1
Screen Shot 2020-05-08 at 10 40 32 AM

Not sure how helpful these views are, so if there's something else we can do locally to provide more useful data, just let us know.

evanweible-wf on 8 May 2020

The Kernel Generate and Compile phases are really where most of the work is happening - CollectDeps is actually just waiting for all deps to be built - so its a bit misleading, but it does indicate that it is taking longer than before to build all the deps.

We haven't really built tools for it but there is also an option to dump the timing data to a file, which would allow a deeper analysis (sum up all the Kernel Generate and Compile steps separately). The Kernel Generate portion looks like it is taking the majority of the time though.

jakemac53 on 11 May 2020

I pushed a tiny little tool that you could hack on to this branch of the timings package, https://github.com/dart-lang/timing/tree/analyze-tool.

You could try running that with one of the outputs of --log-performance, from that repo it would look something like dart bin/analyze.dart --builder-key "build_web_compilers:ddc" --action-label "Kernel Generate" --action-label "Compile" <path-to-performance-data>

This just gives you mean/sum times for those two labeled actions, you could hack on it further to get more data.

jakemac53 on 11 May 2020

👍2

You were spot on, here's from "also huge" package again:

2.7.1

{
  "builder key": "build_web_compilers:ddc",
  "action label": "Compile",
  "mean duration": "0:00:00.258275",
  "total duration": "0:04:14.659452"
}
{
  "builder key": "build_web_compilers:ddc",
  "action label": "Kernel Generate",
  "mean duration": "0:00:00.356165",
  "total duration": "0:05:50.822695"
}
{
  "builder key": "build_web_compilers:ddc",
  "action label": "Build",
  "mean duration": "0:00:00.000055",
  "total duration": "0:00:09.900819"
}

2.8.1

{
  "builder key": "build_web_compilers:ddc",
  "action label": "Compile",
  "mean duration": "0:00:00.342354",
  "total duration": "0:05:37.561355"
}
{
  "builder key": "build_web_compilers:ddc",
  "action label": "Kernel Generate",
  "mean duration": "0:00:00.662882",
  "total duration": "0:10:52.938939"
}
{
  "builder key": "build_web_compilers:ddc",
  "action label": "Build",
  "mean duration": "0:00:00.000076",
  "total duration": "0:00:13.670478"
}

I looked at a few other actions but none had anything close to the difference between the first two in these diffs.

smaifullerton-wk on 12 May 2020

cc @jensjoha how do we get timing information from kernel again?

jakemac53 on 12 May 2020

There should be a verbose flag on the CompilerOptions. It should print stuff to the terminal, I don't know if that helps you?

jensjoha on 12 May 2020

Thanks, that is what I was looking for. Unfortunately it looks like we don't expose that in the bazel worker as an argument though so we can't easily diagnose this.

jakemac53 on 13 May 2020

@jensjoha I am looking at plumbing this flag through, and I have a question about the Severity argument for DiagnosticMessage. Is there a function that I can call somewhere that tells me whether a given severity should result in a build failure?

Today we are just failing the build on any diagnostic message, but adding verbose logging support means we need to distinguish between which ones should fail the build or not.

My current plan is to use a switch so that any new values added would cause a breakage in the code I am adding, forcing somebody to update the switch. I would have the switch fail on internalProblem and error severity, but allow all others.

jakemac53 on 13 May 2020

I think something like

    if (message.severity == Severity.error) {
      hasCompilationErrors = true;
    }

is enough... That's for instance what the VM does.

jensjoha on 14 May 2020

👍1

So, this in on my crappy chromebook which I am relegated to while WFH, but I ran a build in the _test directory of the build repo which is a very minimal project.

The verbose output from the last kernel build was as follows:

Inputs: [org-dartlang-app:///test/common/utils.dart]
Output: null
Was diagnostic message handler provided: yes
FileSystem: Null (provided: MultiRootFileSystem)
Additional Dills:
  - org-dartlang-app:///packages/test_process/test_process.vm.dill
  - org-dartlang-app:///packages/path/path.vm.dill
  - org-dartlang-app:///packages/test/test.vm.dill
  - org-dartlang-app:///packages/meta/meta.vm.dill
  - org-dartlang-app:///packages/async/async.vm.dill
  - org-dartlang-app:///packages/test_core/test_core.vm.dill
  - org-dartlang-app:///packages/collection/collection.vm.dill
  - org-dartlang-app:///packages/matcher/matcher.vm.dill
  - org-dartlang-app:///packages/test_api/src/util/iterable_set.vm.dill
  - org-dartlang-app:///packages/test_core/src/runner/coverage.vm.dill
  - org-dartlang-app:///packages/stack_trace/src/chain.vm.dill
  - org-dartlang-app:///packages/stream_channel/stream_channel.vm.dill
  - org-dartlang-app:///packages/pool/pool.vm.dill
  - org-dartlang-app:///packages/test_api/backend.vm.dill
  - org-dartlang-app:///packages/test_api/src/backend/closed_exception.vm.dill
  - org-dartlang-app:///packages/pedantic/pedantic.vm.dill
  - org-dartlang-app:///packages/test_api/src/backend/metadata.vm.dill
  - org-dartlang-app:///packages/collection/src/algorithms.vm.dill
  - org-dartlang-app:///packages/collection/src/utils.vm.dill
  - org-dartlang-app:///packages/collection/src/iterable_zip.vm.dill
  - org-dartlang-app:///packages/collection/src/comparators.vm.dill
  - org-dartlang-app:///packages/collection/src/priority_queue.vm.dill
  - org-dartlang-app:///packages/collection/src/canonicalized_map.vm.dill
  - org-dartlang-app:///packages/matcher/src/core_matchers.vm.dill
  - org-dartlang-app:///packages/source_span/source_span.vm.dill
  - org-dartlang-app:///packages/boolean_selector/boolean_selector.vm.dill
  - org-dartlang-app:///packages/string_scanner/src/eager_span_scanner.vm.dill
  - org-dartlang-app:///packages/term_glyph/src/generated/ascii_glyph_set.vm.dill
  - org-dartlang-app:///packages/charcode/charcode.vm.dill
  - org-dartlang-app:///packages/charcode/ascii.vm.dill
  - org-dartlang-app:///packages/charcode/html_entity.vm.dill
Packages uri: org-dartlang-app:///.dart_tool/package_config.json
Packages: null
Compile SDK: false
SDK root: null (provided: null)
SDK specification: null (provided: file:///home/jakemac/dart-sdk/lib/libraries.json)
SDK summary: null (provided: file:///home/jakemac/dart-sdk/lib/_internal/vm_platform_strong.dill)
Target: null (provided: vm)
throwOnErrorsForDebugging: false
throwOnWarningsForDebugging: false
exit on problem: false
Embed sources: true
debugDump: false
verbose: true
verify: false

0:00:00.306204: Started building UriTranslator in 306ms.
0:00:00.329969: Read libraries file in 23ms.
0:00:00.347858: Read packages file in 17ms.
0:00:00.948422: Indexed 235 libraries (0 bytes) in 600.490ms, that is,
       0.000 bytes/ms, and
       2.555 ms/libraries.
0:00:00.992616: Built outlines for 1 compilation units (7849 bytes) in 44.064ms, that is,
     178.127 bytes/ms, and
      44.064 ms/compilation unit.
0:00:01.055156: Resolved parts in 62ms.
0:00:01.055243: Applied patches in 0ms.
0:00:01.139915: Computed library scopes in 84ms.
0:00:01.140267: Resolved 98 types in 0ms.
0:00:01.140318: Computed variances of 0 type variables in 0ms.
0:00:01.140371: Computed default types for 0 type variables in 0ms.
0:00:01.140460: Checked class hierarchy in 0ms.
0:00:01.140501: Checked imports and exports for duplicate names in 0ms.
0:00:01.140528: Resolved 0 type-variable bounds in 0ms.
0:00:01.141446: Built component in 0ms.
0:00:01.141523: Installed Object as implicit superclass in 0ms.
0:00:01.141540: Installed synthetic constructors in 0ms.
0:00:01.141584: Resolved 0 constructors in 0ms.
0:00:01.142068: Linked component in 0ms.
0:00:01.144037: Computed core types in 1ms.
0:00:01.144202: Built class hierarchy in 0ms.
0:00:01.184266: Computed class hierarchy in 40ms.
0:00:01.184374: Performed top level inference in 0ms.
0:00:01.184403: Checked supertypes in 0ms.
0:00:01.185668: Checked type arguments of supers against the bounds in 1ms.
0:00:01.185769: Checked 0 overrides in 0ms.
0:00:01.185811: Finished initializing formals in 0ms.
0:00:01.185843: Computed 0 combined member signatures in 0ms.
0:00:01.185874: Updated 0 classes in kernel hierarchy in 0ms.
0:00:01.185926: Added noSuchMethod forwarders in 0ms.
0:00:01.186052: Checked mixin declaration applications in 0ms.
0:00:01.186338: Build outline expressions in 0ms.
0:00:01.186398: Checked redirecting factories in 0ms.
0:00:01.186666: Building component in 0ms.
0:00:01.457629: Built bodies for 1 compilation units (7849 bytes) in 270.906ms, that is,
      28.973 bytes/ms, and
     270.906 ms/compilation unit.
0:00:01.457759: Cloned default values of formals in 0ms.
0:00:01.457792: Finished deferred load tearoffs 0 in 0ms.
0:00:01.457819: Finished forwarders for 0 procedures in 0ms.
0:00:01.457897: Finished 0 native methods in 0ms.
0:00:01.457921: Finished 0 patch methods in 0ms.
0:00:01.457939: Finished constructors in 0ms.
0:00:01.463604: Evaluated constants in 5ms.
0:00:01.463688: Transformed mixin applications in 0ms.
0:00:01.467739: Transformed ffi annotations in 4ms.
0:00:01.510848: Transformed async methods in 43ms.
0:00:01.516094: Specialized list factories in 5ms.
0:00:01.528512: Transformed late variable initializers in 12ms.
0:00:01.545639: Annotated call sites in 17ms.
0:00:01.545909: Generated component in 0ms.

It spent 600ms just "Indexing 235 libraries", so I think something is definitely going on there. I noticed it also didn't start listing any timings at all until 300ms in.

jakemac53 on 14 May 2020

cc @jensjoha do you have an idea what is taking so long there? I noticed it also said it loaded 0 bytes so it seems like it was not really doing anything, like it already had those loaded in memory and was only performing some bookkeeping.

jakemac53 on 14 May 2020

While numbers are good, numbers without anything to compare them with isn't that useful. If it regressed in 2.8.1 you really should compare timings for 2.8.1 vs an older one without the regression.
Regarding the 0 bytes thing is because we - as I recall - add previously loaded libraries; we have no idea how many bytes that was, so we have nothing to report.

jensjoha on 15 May 2020

Ya I agree - its just extremely painful for me to do SDK builds right now (literally takes >1 hour). The speed seemed obviously bad so I thought it was worth pointing out - but as you pointed out in the CL this was for a build not using the incremental compiler (it was a vm build, not a web build, that we were getting numbers for).

I have re-ran with the updates and am getting much more expected numbers (this is for a different module but):

[INFO] build_web_compilers:ddc on test/configurable_uri_test.ddc.module:
0:00:00.000092: Started building UriTranslator in 0ms.
0:00:00.007286: Read libraries file in 7ms.
0:00:00.010141: Read packages file in 2ms.
0:00:00.010226: Read packages file in 0ms.
0:00:00.012115: Decided to reuse 244 of 245 libraries in 1ms.
0:00:00.017553: Built outlines for 3 compilation units (1466 bytes) in 5.409ms, that is,
     271.030 bytes/ms, and
       1.803 ms/compilation unit.
0:00:00.017688: Built outlines for 3 compilation units (1466 bytes) in 0.063ms, that is,
   23269.841 bytes/ms, and
       0.021 ms/compilation unit.
0:00:00.018047: Resolved parts in 0ms.
0:00:00.018093: Applied patches in 0ms.
0:00:00.018872: Computed library scopes in 0ms.
0:00:00.018963: Resolved 2 types in 0ms.
0:00:00.019008: Computed variances of 0 type variables in 0ms.
0:00:00.019060: Computed default types for 0 type variables in 0ms.
0:00:00.019104: Checked class hierarchy in 0ms.
0:00:00.019146: Checked imports and exports for duplicate names in 0ms.
0:00:00.019189: Resolved 0 type-variable bounds in 0ms.
0:00:00.019334: Built component in 0ms.
0:00:00.019379: Installed Object as implicit superclass in 0ms.
0:00:00.019394: Installed synthetic constructors in 0ms.
0:00:00.019436: Resolved 0 constructors in 0ms.
0:00:00.019816: Linked component in 0ms.
0:00:00.020016: Computed core types in 0ms.
0:00:00.020097: Built class hierarchy in 0ms.
0:00:00.020466: Computed class hierarchy in 0ms.
0:00:00.020559: Performed top level inference in 0ms.
0:00:00.020578: Checked supertypes in 0ms.
0:00:00.020637: Checked type arguments of supers against the bounds in 0ms.
0:00:00.020653: Checked 0 overrides in 0ms.
0:00:00.020667: Finished initializing formals in 0ms.
0:00:00.020681: Computed 0 combined member signatures in 0ms.
0:00:00.020694: Updated 0 classes in kernel hierarchy in 0ms.
0:00:00.020708: Added noSuchMethod forwarders in 0ms.
0:00:00.020720: Checked mixin declaration applications in 0ms.
0:00:00.020749: Build outline expressions in 0ms.
0:00:00.020761: Checked redirecting factories in 0ms.
0:00:00.022074: Indexed 247 libraries (0 bytes) in 1.306ms, that is,
       0.000 bytes/ms, and
       0.005 ms/libraries.

I will try and get a patch with these changes to compare things against soon.

jakemac53 on 15 May 2020

@evanweible-wf is your team able to build/run with custom dart SDKs?

jakemac53 on 15 May 2020

I know @robbecker-wf has done it several times, so if you've got a patch for us to try we should be able to figure that out.

evanweible-wf on 15 May 2020

https://github.com/dart-lang/sdk/commit/667e6f96aebbbb1e6cdb77152294a63c2dec0990 is the SDK commit that allows passing --verbose, and then you would need to add these git overrides to your pubspec:

dependency_overrides:
  build_modules:
    git:
      url: https://github.com/dart-lang/build.git
      ref: use-verbose-option
      path: build_modules
  build_web_compilers:
    git:
      url: https://github.com/dart-lang/build.git
      ref: use-verbose-option
      path: build_web_compilers

Then you would additionally need to set the verbose option to true for the build_web_compilers|ddc builder.

Once a dev sdk is released supporting --verbose, I can publish actual versions.

jakemac53 on 15 May 2020

@jakemac53 Here is a sampling of the logs from a smaller package using the SDK commit. I couldn't build the larger app due to range conflicts with the build_x package overrides.

[INFO] build_web_compilers:ddc on package:web_skin/web_skin.ddc.module:
0:00:00.000087: Started building UriTranslator in 0ms.
0:00:00.003347: Read libraries file in 3ms.
0:00:00.006607: Read packages file in 3ms.
0:00:00.006678: Read packages file in 0ms.
0:00:00.008406: Decided to reuse 179 of 182 libraries in 1ms.
0:00:00.073755: Built outlines for 6 compilation units (2597135 bytes) in 65.327ms, that is,
   39755.920 bytes/ms, and
      10.888 ms/compilation unit.
0:00:00.073873: Built outlines for 6 compilation units (2597135 bytes) in 0.051ms, that is,
50924215.686 bytes/ms, and
       0.008 ms/compilation unit.
0:00:00.074113: Resolved parts in 0ms.
0:00:00.074142: Applied patches in 0ms.
0:00:00.074636: Computed library scopes in 0ms.
0:00:00.075392: Resolved 3092 types in 0ms.
0:00:00.075440: Computed variances of 0 type variables in 0ms.
0:00:00.075711: Computed default types for 0 type variables in 0ms.
0:00:00.075760: Checked class hierarchy in 0ms.
0:00:00.075785: Checked imports and exports for duplicate names in 0ms.
0:00:00.075802: Resolved 0 type-variable bounds in 0ms.
0:00:00.079340: Built component in 3ms.
0:00:00.079581: Installed Object as implicit superclass in 0ms.
0:00:00.079643: Installed synthetic constructors in 0ms.
0:00:00.079696: Resolved 0 constructors in 0ms.
0:00:00.079980: Linked component in 0ms.
0:00:00.080126: Computed core types in 0ms.
0:00:00.083876: Built class hierarchy in 3ms.
0:00:00.084252: Computed class hierarchy in 0ms.
0:00:00.085121: Performed top level inference in 0ms.
0:00:00.085157: Checked supertypes in 0ms.
0:00:00.115427: Checked type arguments of supers against the bounds in 30ms.
0:00:00.115479: Checked 3 overrides in 0ms.
0:00:00.115506: Finished initializing formals in 0ms.
0:00:00.115666: Computed 32 combined member signatures in 0ms.
0:00:00.115682: Updated 7 classes in kernel hierarchy in 0ms.
0:00:00.115880: Added noSuchMethod forwarders in 0ms.
0:00:00.115887: Checked mixin declaration applications in 0ms.
0:00:00.530133: Build outline expressions in 414ms.
0:00:00.530175: Checked redirecting factories in 0ms.
0:00:00.532638: Indexed 184 libraries (0 bytes) in 2.458ms, that is,
       0.000 bytes/ms, and
       0.013 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/ui_components/grid_frame.ddc.module:
0:00:00.000060: Started building UriTranslator in 0ms.
0:00:00.002229: Read libraries file in 2ms.
0:00:00.004372: Read packages file in 2ms.
0:00:00.004418: Read packages file in 0ms.
0:00:00.005538: Decided to reuse 177 of 179 libraries in 1ms.
0:00:00.019768: Built outlines for 3 compilation units (6402 bytes) in 14.209ms, that is,
     450.560 bytes/ms, and
       4.736 ms/compilation unit.
0:00:00.019881: Built outlines for 3 compilation units (6402 bytes) in 0.052ms, that is,
  123115.385 bytes/ms, and
       0.017 ms/compilation unit.
0:00:00.020057: Resolved parts in 0ms.
0:00:00.020080: Applied patches in 0ms.
0:00:00.020580: Computed library scopes in 0ms.
0:00:00.020681: Resolved 49 types in 0ms.
0:00:00.020703: Computed variances of 0 type variables in 0ms.
0:00:00.020747: Computed default types for 0 type variables in 0ms.
0:00:00.020806: Checked class hierarchy in 0ms.
0:00:00.020832: Checked imports and exports for duplicate names in 0ms.
0:00:00.020853: Resolved 0 type-variable bounds in 0ms.
0:00:00.021169: Built component in 0ms.
0:00:00.021195: Installed Object as implicit superclass in 0ms.
0:00:00.021259: Installed synthetic constructors in 0ms.
0:00:00.021289: Resolved 0 constructors in 0ms.
0:00:00.021466: Linked component in 0ms.
0:00:00.021563: Computed core types in 0ms.
0:00:00.040892: Built class hierarchy in 19ms.
0:00:00.041305: Computed class hierarchy in 0ms.
0:00:00.042385: Performed top level inference in 1ms.
0:00:00.042444: Checked supertypes in 0ms.
0:00:00.042658: Checked type arguments of supers against the bounds in 0ms.
0:00:00.044561: Checked 343 overrides in 1ms.
0:00:00.044587: Finished initializing formals in 0ms.
0:00:00.054786: Computed 2724 combined member signatures in 10ms.
0:00:00.054843: Updated 50 classes in kernel hierarchy in 0ms.
0:00:00.057944: Added noSuchMethod forwarders in 3ms.
0:00:00.057975: Checked mixin declaration applications in 0ms.
0:00:00.058578: Build outline expressions in 0ms.
0:00:00.058599: Checked redirecting factories in 0ms.
0:00:00.059615: Indexed 179 libraries (0 bytes) in 1.014ms, that is,
       0.000 bytes/ms, and
       0.006 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/src/ui_components/button/button_toolbar.ddc.module:
0:00:00.000047: Started building UriTranslator in 0ms.
0:00:00.001792: Read libraries file in 1ms.
0:00:00.004916: Read packages file in 3ms.
0:00:00.004994: Read packages file in 0ms.
0:00:00.006437: Decided to reuse 177 of 184 libraries in 1ms.
0:00:00.019138: Built outlines for 2 compilation units (6664 bytes) in 12.686ms, that is,
     525.303 bytes/ms, and
       6.343 ms/compilation unit.
0:00:00.019225: Built outlines for 2 compilation units (6664 bytes) in 0.041ms, that is,
  162536.585 bytes/ms, and
       0.021 ms/compilation unit.
0:00:00.019476: Resolved parts in 0ms.
0:00:00.019506: Applied patches in 0ms.
0:00:00.020040: Computed library scopes in 0ms.
0:00:00.020130: Resolved 49 types in 0ms.
0:00:00.020156: Computed variances of 0 type variables in 0ms.
0:00:00.020205: Computed default types for 0 type variables in 0ms.
0:00:00.020284: Checked class hierarchy in 0ms.
0:00:00.020311: Checked imports and exports for duplicate names in 0ms.
0:00:00.020349: Resolved 0 type-variable bounds in 0ms.
0:00:00.020632: Built component in 0ms.
0:00:00.020672: Installed Object as implicit superclass in 0ms.
0:00:00.020753: Installed synthetic constructors in 0ms.
0:00:00.020790: Resolved 0 constructors in 0ms.
0:00:00.021100: Linked component in 0ms.
0:00:00.021176: Computed core types in 0ms.
0:00:00.040380: Built class hierarchy in 19ms.
0:00:00.040795: Computed class hierarchy in 0ms.
0:00:00.041674: Performed top level inference in 0ms.
0:00:00.041711: Checked supertypes in 0ms.
0:00:00.041851: Checked type arguments of supers against the bounds in 0ms.
0:00:00.043415: Checked 343 overrides in 1ms.
0:00:00.043437: Finished initializing formals in 0ms.
0:00:00.066479: Computed 2724 combined member signatures in 23ms.
0:00:00.066540: Updated 50 classes in kernel hierarchy in 0ms.
0:00:00.071356: Added noSuchMethod forwarders in 4ms.
0:00:00.071390: Checked mixin declaration applications in 0ms.
0:00:00.072305: Build outline expressions in 0ms.
0:00:00.072341: Checked redirecting factories in 0ms.
0:00:00.073526: Indexed 178 libraries (0 bytes) in 1.181ms, that is,
       0.000 bytes/ms, and
       0.007 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/src/ui_components/common/layout/grid/grid_frame.ddc.module:
0:00:00.000066: Started building UriTranslator in 0ms.
0:00:00.002694: Read libraries file in 2ms.
0:00:00.005846: Read packages file in 3ms.
0:00:00.005933: Read packages file in 0ms.
0:00:00.009091: Decided to reuse 59 of 332 libraries in 3ms.
0:00:00.012377: Indexed 177 libraries (0 bytes) in 3.268ms, that is,
       0.000 bytes/ms, and
       0.018 ms/libraries.
0:00:00.017453: Built outlines for 2 compilation units (6268 bytes) in 4.996ms, that is,
    1254.604 bytes/ms, and
       2.498 ms/compilation unit.
0:00:00.017533: Built outlines for 2 compilation units (6268 bytes) in 0.034ms, that is,
  184352.941 bytes/ms, and
       0.017 ms/compilation unit.
0:00:00.017654: Resolved parts in 0ms.
0:00:00.017670: Applied patches in 0ms.
0:00:00.027365: Computed library scopes in 9ms.
0:00:00.027518: Resolved 49 types in 0ms.
0:00:00.027567: Computed variances of 0 type variables in 0ms.
0:00:00.027638: Computed default types for 0 type variables in 0ms.
0:00:00.027711: Checked class hierarchy in 0ms.
0:00:00.027755: Checked imports and exports for duplicate names in 0ms.
0:00:00.027781: Resolved 0 type-variable bounds in 0ms.
0:00:00.028154: Built component in 0ms.
0:00:00.028209: Installed Object as implicit superclass in 0ms.
0:00:00.028293: Installed synthetic constructors in 0ms.
0:00:00.028328: Resolved 0 constructors in 0ms.
0:00:00.028537: Linked component in 0ms.
0:00:00.029040: Computed core types in 0ms.
0:00:00.071447: Built class hierarchy in 42ms.
0:00:00.075898: Computed class hierarchy in 4ms.
0:00:00.091831: Performed top level inference in 15ms.
0:00:00.091880: Checked supertypes in 0ms.
0:00:00.092686: Checked type arguments of supers against the bounds in 0ms.
0:00:00.096595: Checked 343 overrides in 3ms.
0:00:00.096627: Finished initializing formals in 0ms.
0:00:00.127441: Computed 2724 combined member signatures in 30ms.
0:00:00.127547: Updated 50 classes in kernel hierarchy in 0ms.
0:00:00.132515: Added noSuchMethod forwarders in 4ms.
0:00:00.132553: Checked mixin declaration applications in 0ms.
0:00:00.133763: Build outline expressions in 1ms.
0:00:00.133810: Checked redirecting factories in 0ms.
0:00:00.135832: Indexed 178 libraries (0 bytes) in 2.019ms, that is,
       0.000 bytes/ms, and
       0.011 ms/libraries.
[INFO] build_web_compilers:ddc on package:key_binder/dom.ddc.module:
0:00:00.000062: Started building UriTranslator in 0ms.
0:00:00.002481: Read libraries file in 2ms.
0:00:00.005732: Read packages file in 3ms.
0:00:00.005793: Read packages file in 0ms.
0:00:00.007332: Decided to reuse 177 of 178 libraries in 1ms.
0:00:00.007514: Indexed 178 libraries (0 bytes) in 0.165ms, that is,
       0.000 bytes/ms, and
       0.001 ms/libraries.
0:00:00.040911: Built outlines for 15 compilation units (48103 bytes) in 33.358ms, that is,
    1442.023 bytes/ms, and
       2.224 ms/compilation unit.
0:00:00.041004: Built outlines for 15 compilation units (48103 bytes) in 0.045ms, that is,
 1068955.556 bytes/ms, and
       0.003 ms/compilation unit.
0:00:00.041112: Resolved parts in 0ms.
0:00:00.041136: Applied patches in 0ms.
0:00:00.043388: Computed library scopes in 2ms.
0:00:00.043561: Resolved 293 types in 0ms.
0:00:00.043620: Computed variances of 0 type variables in 0ms.
0:00:00.043713: Computed default types for 0 type variables in 0ms.
0:00:00.043837: Checked class hierarchy in 0ms.
0:00:00.043862: Checked imports and exports for duplicate names in 0ms.
0:00:00.043891: Resolved 0 type-variable bounds in 0ms.
0:00:00.044797: Built component in 0ms.
0:00:00.044854: Installed Object as implicit superclass in 0ms.
0:00:00.044917: Installed synthetic constructors in 0ms.
0:00:00.044959: Resolved 0 constructors in 0ms.
0:00:00.045147: Linked component in 0ms.
0:00:00.045239: Computed core types in 0ms.
0:00:00.048202: Built class hierarchy in 2ms.
0:00:00.048641: Computed class hierarchy in 0ms.
0:00:00.049339: Performed top level inference in 0ms.
0:00:00.049387: Checked supertypes in 0ms.
0:00:00.050057: Checked type arguments of supers against the bounds in 0ms.
0:00:00.050329: Checked 69 overrides in 0ms.
0:00:00.050389: Finished initializing formals in 0ms.
0:00:00.052163: Computed 183 combined member signatures in 1ms.
0:00:00.052215: Updated 22 classes in kernel hierarchy in 0ms.
0:00:00.052981: Added noSuchMethod forwarders in 0ms.
0:00:00.053008: Checked mixin declaration applications in 0ms.
0:00:00.054118: Build outline expressions in 1ms.
0:00:00.054163: Checked redirecting factories in 0ms.
0:00:00.055692: Indexed 193 libraries (0 bytes) in 1.524ms, that is,
       0.000 bytes/ms, and
       0.008 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/src/internals/flatten_children.ddc.module:
0:00:00.000057: Started building UriTranslator in 0ms.
0:00:00.002392: Read libraries file in 2ms.
0:00:00.005147: Read packages file in 2ms.
0:00:00.005199: Read packages file in 0ms.
0:00:00.006219: Decided to reuse 177 of 179 libraries in 1ms.
0:00:00.048306: Built outlines for 7 compilation units (43921 bytes) in 42.074ms, that is,
    1043.899 bytes/ms, and
       6.011 ms/compilation unit.
0:00:00.048415: Built outlines for 7 compilation units (43921 bytes) in 0.058ms, that is,
  757258.621 bytes/ms, and
       0.008 ms/compilation unit.
0:00:00.048725: Resolved parts in 0ms.
0:00:00.048756: Applied patches in 0ms.
0:00:00.049429: Computed library scopes in 0ms.
0:00:00.049706: Resolved 253 types in 0ms.
0:00:00.049748: Computed variances of 0 type variables in 0ms.
0:00:00.049840: Computed default types for 0 type variables in 0ms.
0:00:00.049955: Checked class hierarchy in 0ms.
0:00:00.049984: Checked imports and exports for duplicate names in 0ms.
0:00:00.050008: Resolved 0 type-variable bounds in 0ms.
0:00:00.051133: Built component in 1ms.
0:00:00.051187: Installed Object as implicit superclass in 0ms.
0:00:00.051322: Installed synthetic constructors in 0ms.
0:00:00.051370: Resolved 0 constructors in 0ms.
0:00:00.051543: Linked component in 0ms.
0:00:00.051636: Computed core types in 0ms.
0:00:00.092578: Built class hierarchy in 40ms.
0:00:00.093143: Computed class hierarchy in 0ms.
0:00:00.094248: Performed top level inference in 1ms.
0:00:00.094293: Checked supertypes in 0ms.
0:00:00.094708: Checked type arguments of supers against the bounds in 0ms.
0:00:00.096774: Checked 507 overrides in 2ms.
0:00:00.096796: Finished initializing formals in 0ms.
0:00:00.133883: Computed 5706 combined member signatures in 37ms.
0:00:00.133991: Updated 70 classes in kernel hierarchy in 0ms.
0:00:00.144572: Added noSuchMethod forwarders in 10ms.
0:00:00.144614: Checked mixin declaration applications in 0ms.
0:00:00.152196: Build outline expressions in 7ms.
0:00:00.152243: Checked redirecting factories in 0ms.
0:00:00.153560: Indexed 181 libraries (0 bytes) in 1.312ms, that is,
       0.000 bytes/ms, and
       0.007 ms/libraries.
[INFO] build_web_compilers:ddc on package:messaging_sdk/messaging_sdk.ddc.module:
0:00:00.000062: Started building UriTranslator in 0ms.
0:00:00.002325: Read libraries file in 2ms.
0:00:00.005253: Read packages file in 2ms.
0:00:00.005316: Read packages file in 0ms.
0:00:00.007381: Decided to reuse 59 of 181 libraries in 2ms.
0:00:00.011168: Indexed 269 libraries (0 bytes) in 3.770ms, that is,
       0.000 bytes/ms, and
       0.014 ms/libraries.
0:00:00.150267: Built outlines for 29 compilation units (95303 bytes) in 139.038ms, that is,
     685.446 bytes/ms, and
       4.794 ms/compilation unit.
0:00:00.150437: Built outlines for 29 compilation units (95303 bytes) in 0.061ms, that is,
 1562344.262 bytes/ms, and
       0.002 ms/compilation unit.
0:00:00.150855: Resolved parts in 0ms.
0:00:00.150894: Applied patches in 0ms.
0:00:00.156701: Computed library scopes in 5ms.
0:00:00.157402: Resolved 654 types in 0ms.
0:00:00.157480: Computed variances of 0 type variables in 0ms.
0:00:00.157647: Computed default types for 0 type variables in 0ms.
0:00:00.157781: Checked class hierarchy in 0ms.
0:00:00.157838: Checked imports and exports for duplicate names in 0ms.
0:00:00.157872: Resolved 0 type-variable bounds in 0ms.
0:00:00.159643: Built component in 1ms.
0:00:00.159752: Installed Object as implicit superclass in 0ms.
0:00:00.159892: Installed synthetic constructors in 0ms.
0:00:00.159974: Resolved 0 constructors in 0ms.
0:00:00.160288: Linked component in 0ms.
0:00:00.160421: Computed core types in 0ms.
0:00:00.165760: Built class hierarchy in 5ms.
0:00:00.168151: Computed class hierarchy in 2ms.
0:00:00.169926: Performed top level inference in 1ms.
0:00:00.169984: Checked supertypes in 0ms.
0:00:00.170984: Checked type arguments of supers against the bounds in 0ms.
0:00:00.171366: Checked 149 overrides in 0ms.
0:00:00.171458: Finished initializing formals in 0ms.
0:00:00.174547: Computed 519 combined member signatures in 3ms.
0:00:00.174610: Updated 67 classes in kernel hierarchy in 0ms.
0:00:00.176540: Added noSuchMethod forwarders in 1ms.
0:00:00.176582: Checked mixin declaration applications in 0ms.
0:00:00.190665: Build outline expressions in 14ms.
0:00:00.190721: Checked redirecting factories in 0ms.
0:00:00.192359: Indexed 274 libraries (0 bytes) in 1.630ms, that is,
       0.000 bytes/ms, and
       0.006 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/ui_components/button_toolbar.ddc.module:
0:00:00.000060: Started building UriTranslator in 0ms.
0:00:00.002585: Read libraries file in 2ms.
0:00:00.005558: Read packages file in 2ms.
0:00:00.005615: Read packages file in 0ms.
0:00:00.008254: Decided to reuse 59 of 274 libraries in 2ms.
0:00:00.010749: Indexed 177 libraries (0 bytes) in 2.474ms, that is,
       0.000 bytes/ms, and
       0.014 ms/libraries.
0:00:00.019023: Built outlines for 3 compilation units (6794 bytes) in 8.212ms, that is,
     827.326 bytes/ms, and
       2.737 ms/compilation unit.
0:00:00.019136: Built outlines for 3 compilation units (6794 bytes) in 0.051ms, that is,
  133215.686 bytes/ms, and
       0.017 ms/compilation unit.
0:00:00.019479: Resolved parts in 0ms.
0:00:00.019507: Applied patches in 0ms.
0:00:00.023563: Computed library scopes in 4ms.
0:00:00.023729: Resolved 49 types in 0ms.
0:00:00.023767: Computed variances of 0 type variables in 0ms.
0:00:00.023820: Computed default types for 0 type variables in 0ms.
0:00:00.023894: Checked class hierarchy in 0ms.
0:00:00.023925: Checked imports and exports for duplicate names in 0ms.
0:00:00.023949: Resolved 0 type-variable bounds in 0ms.
0:00:00.024295: Built component in 0ms.
0:00:00.024329: Installed Object as implicit superclass in 0ms.
0:00:00.024404: Installed synthetic constructors in 0ms.
0:00:00.024440: Resolved 0 constructors in 0ms.
0:00:00.024647: Linked component in 0ms.
0:00:00.024767: Computed core types in 0ms.
0:00:00.049349: Built class hierarchy in 24ms.
0:00:00.054494: Computed class hierarchy in 5ms.
0:00:00.055184: Performed top level inference in 0ms.
0:00:00.055221: Checked supertypes in 0ms.
0:00:00.055440: Checked type arguments of supers against the bounds in 0ms.
0:00:00.057260: Checked 343 overrides in 1ms.
0:00:00.057282: Finished initializing formals in 0ms.
0:00:00.070233: Computed 2724 combined member signatures in 12ms.
0:00:00.070290: Updated 50 classes in kernel hierarchy in 0ms.
0:00:00.073302: Added noSuchMethod forwarders in 3ms.
0:00:00.073330: Checked mixin declaration applications in 0ms.
0:00:00.074137: Build outline expressions in 0ms.
0:00:00.074164: Checked redirecting factories in 0ms.
0:00:00.075335: Indexed 179 libraries (0 bytes) in 1.167ms, that is,
       0.000 bytes/ms, and
       0.007 ms/libraries.
[INFO] build_web_compilers:ddc on package:w_virtual_components/src/item_size_collection.ddc.module:
0:00:00.000058: Started building UriTranslator in 0ms.
0:00:00.002442: Read libraries file in 2ms.
0:00:00.005613: Read packages file in 3ms.
0:00:00.005677: Read packages file in 0ms.
0:00:00.007454: Decided to reuse 177 of 193 libraries in 1ms.
0:00:00.009159: Indexed 254 libraries (0 bytes) in 1.681ms, that is,
       0.000 bytes/ms, and
       0.007 ms/libraries.
0:00:00.140729: Built outlines for 31 compilation units (381072 bytes) in 131.527ms, that is,
    2897.291 bytes/ms, and
       4.243 ms/compilation unit.
0:00:00.140819: Built outlines for 31 compilation units (381072 bytes) in 0.039ms, that is,
 9771076.923 bytes/ms, and
       0.001 ms/compilation unit.
0:00:00.141167: Resolved parts in 0ms.
0:00:00.141209: Applied patches in 0ms.
0:00:00.182205: Computed library scopes in 40ms.
0:00:00.184549: Resolved 2065 types in 2ms.
0:00:00.184654: Computed variances of 0 type variables in 0ms.
0:00:00.185207: Computed default types for 5 type variables in 0ms.
0:00:00.185537: Checked class hierarchy in 0ms.
0:00:00.185600: Checked imports and exports for duplicate names in 0ms.
0:00:00.185657: Resolved 5 type-variable bounds in 0ms.
0:00:00.194701: Built component in 9ms.
0:00:00.194845: Installed Object as implicit superclass in 0ms.
0:00:00.195757: Installed synthetic constructors in 0ms.
0:00:00.195925: Resolved 0 constructors in 0ms.
0:00:00.196242: Linked component in 0ms.
0:00:00.196389: Computed core types in 0ms.
0:00:00.353003: Built class hierarchy in 156ms.
0:00:00.369155: Computed class hierarchy in 16ms.
0:00:00.391337: Performed top level inference in 22ms.
0:00:00.391447: Checked supertypes in 0ms.
0:00:00.396429: Checked type arguments of supers against the bounds in 4ms.
0:00:00.406044: Checked 1421 overrides in 9ms.
0:00:00.406128: Finished initializing formals in 0ms.
0:00:00.584383: Computed 9439 combined member signatures in 178ms.
0:00:00.584482: Updated 163 classes in kernel hierarchy in 0ms.
0:00:00.620878: Added noSuchMethod forwarders in 36ms.
0:00:00.623168: Checked mixin declaration applications in 2ms.
0:00:00.669644: Build outline expressions in 46ms.
0:00:00.669749: Checked redirecting factories in 0ms.
0:00:00.672083: Indexed 280 libraries (0 bytes) in 2.323ms, that is,
       0.000 bytes/ms, and
       0.008 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/layout.ddc.module:
0:00:00.000062: Started building UriTranslator in 0ms.
0:00:00.002424: Read libraries file in 2ms.
0:00:00.005504: Read packages file in 3ms.
0:00:00.005570: Read packages file in 0ms.
0:00:00.007220: Decided to reuse 177 of 178 libraries in 1ms.
0:00:00.182752: Built outlines for 33 compilation units (310968 bytes) in 175.512ms, that is,
    1771.776 bytes/ms, and
       5.319 ms/compilation unit.
0:00:00.182897: Built outlines for 33 compilation units (310968 bytes) in 0.065ms, that is,
 4784123.077 bytes/ms, and
       0.002 ms/compilation unit.
0:00:00.183309: Resolved parts in 0ms.
0:00:00.183342: Applied patches in 0ms.
0:00:00.185506: Computed library scopes in 2ms.
0:00:00.186460: Resolved 1262 types in 0ms.
0:00:00.186550: Computed variances of 0 type variables in 0ms.
0:00:00.187066: Computed default types for 5 type variables in 0ms.
0:00:00.187530: Checked class hierarchy in 0ms.
0:00:00.187601: Checked imports and exports for duplicate names in 0ms.
0:00:00.187657: Resolved 5 type-variable bounds in 0ms.
0:00:00.190393: Built component in 2ms.
0:00:00.190611: Installed Object as implicit superclass in 0ms.
0:00:00.191108: Installed synthetic constructors in 0ms.
0:00:00.191249: Resolved 0 constructors in 0ms.
0:00:00.191540: Linked component in 0ms.
0:00:00.191664: Computed core types in 0ms.
0:00:00.467743: Built class hierarchy in 276ms.
0:00:00.475417: Computed class hierarchy in 7ms.
0:00:00.492090: Performed top level inference in 16ms.
0:00:00.492233: Checked supertypes in 0ms.
0:00:00.493888: Checked type arguments of supers against the bounds in 1ms.
0:00:00.501198: Checked 1127 overrides in 7ms.
0:00:00.501262: Finished initializing formals in 0ms.
0:00:00.731892: Computed 20588 combined member signatures in 230ms.
0:00:00.732005: Updated 176 classes in kernel hierarchy in 0ms.
0:00:00.791781: Added noSuchMethod forwarders in 59ms.
0:00:00.791901: Checked mixin declaration applications in 0ms.
0:00:00.824460: Build outline expressions in 32ms.
0:00:00.824585: Checked redirecting factories in 0ms.
0:00:00.826779: Indexed 198 libraries (0 bytes) in 2.183ms, that is,
       0.000 bytes/ms, and
       0.011 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/src/internals/dom_node_measuring_utils.ddc.module:
0:00:00.000062: Started building UriTranslator in 0ms.
0:00:00.002438: Read libraries file in 2ms.
0:00:00.005528: Read packages file in 3ms.
0:00:00.005602: Read packages file in 0ms.
0:00:00.007404: Decided to reuse 177 of 179 libraries in 1ms.
0:00:00.007734: Indexed 184 libraries (0 bytes) in 0.307ms, that is,
       0.000 bytes/ms, and
       0.002 ms/libraries.
0:00:00.190244: Built outlines for 35 compilation units (149401 bytes) in 182.462ms, that is,
     818.806 bytes/ms, and
       5.213 ms/compilation unit.
0:00:00.190351: Built outlines for 35 compilation units (149401 bytes) in 0.047ms, that is,
 3178744.681 bytes/ms, and
       0.001 ms/compilation unit.
0:00:00.190587: Resolved parts in 0ms.
0:00:00.190615: Applied patches in 0ms.
0:00:00.214393: Computed library scopes in 23ms.
0:00:00.215512: Resolved 839 types in 1ms.
0:00:00.215648: Computed variances of 14 type variables in 0ms.
0:00:00.217203: Computed default types for 23 type variables in 1ms.
0:00:00.217445: Checked class hierarchy in 0ms.
0:00:00.217623: Checked imports and exports for duplicate names in 0ms.
0:00:00.217742: Resolved 24 type-variable bounds in 0ms.
0:00:00.229936: Built component in 12ms.
0:00:00.230054: Installed Object as implicit superclass in 0ms.
0:00:00.230341: Installed synthetic constructors in 0ms.
0:00:00.230457: Resolved 0 constructors in 0ms.
0:00:00.230659: Linked component in 0ms.
0:00:00.230774: Computed core types in 0ms.
0:00:00.285877: Built class hierarchy in 55ms.
0:00:00.286610: Computed class hierarchy in 0ms.
0:00:00.287890: Performed top level inference in 1ms.
0:00:00.287966: Checked supertypes in 0ms.
0:00:00.289311: Checked type arguments of supers against the bounds in 1ms.
0:00:00.291636: Checked 560 overrides in 2ms.
0:00:00.291695: Finished initializing formals in 0ms.
0:00:00.334120: Computed 7323 combined member signatures in 42ms.
0:00:00.334205: Updated 132 classes in kernel hierarchy in 0ms.
0:00:00.360279: Added noSuchMethod forwarders in 26ms.
0:00:00.360328: Checked mixin declaration applications in 0ms.
0:00:00.395914: Build outline expressions in 35ms.
0:00:00.396007: Checked redirecting factories in 0ms.
0:00:00.398540: Indexed 213 libraries (0 bytes) in 2.526ms, that is,
       0.000 bytes/ms, and
       0.012 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/ui_core.ddc.module:
0:00:00.000060: Started building UriTranslator in 0ms.
0:00:00.003258: Read libraries file in 3ms.
0:00:00.010460: Read packages file in 7ms.
0:00:00.010586: Read packages file in 0ms.
0:00:00.012844: Decided to reuse 177 of 280 libraries in 2ms.
0:00:00.013176: Indexed 184 libraries (0 bytes) in 0.311ms, that is,
       0.000 bytes/ms, and
       0.002 ms/libraries.
0:00:00.043135: Built outlines for 13 compilation units (37012 bytes) in 29.916ms, that is,
    1237.197 bytes/ms, and
       2.301 ms/compilation unit.
0:00:00.043271: Built outlines for 13 compilation units (37012 bytes) in 0.066ms, that is,
  560787.879 bytes/ms, and
       0.005 ms/compilation unit.
0:00:00.043417: Resolved parts in 0ms.
0:00:00.043445: Applied patches in 0ms.
0:00:00.055784: Computed library scopes in 12ms.
0:00:00.056178: Resolved 282 types in 0ms.
0:00:00.056274: Computed variances of 14 type variables in 0ms.
0:00:00.056974: Computed default types for 18 type variables in 0ms.
0:00:00.057075: Checked class hierarchy in 0ms.
0:00:00.057115: Checked imports and exports for duplicate names in 0ms.
0:00:00.057175: Resolved 19 type-variable bounds in 0ms.
0:00:00.066419: Built component in 9ms.
0:00:00.066493: Installed Object as implicit superclass in 0ms.
0:00:00.066529: Installed synthetic constructors in 0ms.
0:00:00.066585: Resolved 0 constructors in 0ms.
0:00:00.066786: Linked component in 0ms.
0:00:00.066878: Computed core types in 0ms.
0:00:00.077219: Built class hierarchy in 10ms.
0:00:00.077603: Computed class hierarchy in 0ms.
0:00:00.077765: Performed top level inference in 0ms.
0:00:00.077789: Checked supertypes in 0ms.
0:00:00.078591: Checked type arguments of supers against the bounds in 0ms.
0:00:00.079450: Checked 256 overrides in 0ms.
0:00:00.079494: Finished initializing formals in 0ms.
0:00:00.081123: Computed 1195 combined member signatures in 1ms.
0:00:00.081159: Updated 31 classes in kernel hierarchy in 0ms.
0:00:00.081882: Added noSuchMethod forwarders in 0ms.
0:00:00.081903: Checked mixin declaration applications in 0ms.
0:00:00.090562: Build outline expressions in 8ms.
0:00:00.090624: Checked redirecting factories in 0ms.
0:00:00.092766: Indexed 197 libraries (0 bytes) in 2.136ms, that is,
       0.000 bytes/ms, and
       0.011 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/src/ui_components/colorpicker/abstract_color_swatch.ddc.module:
0:00:00.000071: Started building UriTranslator in 0ms.
0:00:00.002496: Read libraries file in 2ms.
0:00:00.005445: Read packages file in 2ms.
0:00:00.005512: Read packages file in 0ms.
0:00:00.007172: Decided to reuse 184 of 213 libraries in 1ms.
0:00:00.023520: Built outlines for 4 compilation units (34668 bytes) in 16.332ms, that is,
    2122.704 bytes/ms, and
       4.083 ms/compilation unit.
0:00:00.023629: Built outlines for 4 compilation units (34668 bytes) in 0.057ms, that is,
  608210.526 bytes/ms, and
       0.014 ms/compilation unit.
0:00:00.023856: Resolved parts in 0ms.
0:00:00.023883: Applied patches in 0ms.
0:00:00.024649: Computed library scopes in 0ms.
0:00:00.024829: Resolved 203 types in 0ms.
0:00:00.024863: Computed variances of 0 type variables in 0ms.
0:00:00.025000: Computed default types for 3 type variables in 0ms.
0:00:00.025073: Checked class hierarchy in 0ms.
0:00:00.025127: Checked imports and exports for duplicate names in 0ms.
0:00:00.025169: Resolved 3 type-variable bounds in 0ms.
0:00:00.025911: Built component in 0ms.
0:00:00.025952: Installed Object as implicit superclass in 0ms.
0:00:00.026017: Installed synthetic constructors in 0ms.
0:00:00.026051: Resolved 0 constructors in 0ms.
0:00:00.026231: Linked component in 0ms.
0:00:00.026336: Computed core types in 0ms.
0:00:00.037715: Built class hierarchy in 11ms.
0:00:00.038072: Computed class hierarchy in 0ms.
0:00:00.038288: Performed top level inference in 0ms.
0:00:00.038315: Checked supertypes in 0ms.
0:00:00.038861: Checked type arguments of supers against the bounds in 0ms.
0:00:00.039709: Checked 269 overrides in 0ms.
0:00:00.039756: Finished initializing formals in 0ms.
0:00:00.045741: Computed 1707 combined member signatures in 5ms.
0:00:00.045798: Updated 48 classes in kernel hierarchy in 0ms.
0:00:00.046036: Added noSuchMethod forwarders in 0ms.
0:00:00.046057: Checked mixin declaration applications in 0ms.
0:00:00.055369: Build outline expressions in 9ms.
0:00:00.055409: Checked redirecting factories in 0ms.
0:00:00.056844: Indexed 187 libraries (0 bytes) in 1.430ms, that is,
       0.000 bytes/ms, and
       0.008 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/src/ui_components/colorpicker/palette_color.ddc.module:
0:00:00.000061: Started building UriTranslator in 0ms.
0:00:00.002897: Read libraries file in 2ms.
0:00:00.006048: Read packages file in 3ms.
0:00:00.006123: Read packages file in 0ms.
0:00:00.008162: Decided to reuse 177 of 198 libraries in 2ms.
0:00:00.008527: Indexed 184 libraries (0 bytes) in 0.343ms, that is,
       0.000 bytes/ms, and
       0.002 ms/libraries.
0:00:00.030495: Built outlines for 12 compilation units (36203 bytes) in 21.912ms, that is,
    1652.200 bytes/ms, and
       1.826 ms/compilation unit.
0:00:00.030622: Built outlines for 12 compilation units (36203 bytes) in 0.058ms, that is,
  624189.655 bytes/ms, and
       0.005 ms/compilation unit.
0:00:00.030765: Resolved parts in 0ms.
0:00:00.030790: Applied patches in 0ms.
0:00:00.042945: Computed library scopes in 12ms.
0:00:00.043279: Resolved 282 types in 0ms.
0:00:00.043368: Computed variances of 14 type variables in 0ms.
0:00:00.043768: Computed default types for 18 type variables in 0ms.
0:00:00.043899: Checked class hierarchy in 0ms.
0:00:00.043961: Checked imports and exports for duplicate names in 0ms.
0:00:00.044027: Resolved 19 type-variable bounds in 0ms.
0:00:00.045642: Built component in 1ms.
0:00:00.045737: Installed Object as implicit superclass in 0ms.
0:00:00.045775: Installed synthetic constructors in 0ms.
0:00:00.045825: Resolved 0 constructors in 0ms.
0:00:00.046206: Linked component in 0ms.
0:00:00.046352: Computed core types in 0ms.
0:00:00.056161: Built class hierarchy in 9ms.
0:00:00.056866: Computed class hierarchy in 0ms.
0:00:00.057056: Performed top level inference in 0ms.
0:00:00.057090: Checked supertypes in 0ms.
0:00:00.057537: Checked type arguments of supers against the bounds in 0ms.
0:00:00.058315: Checked 256 overrides in 0ms.
0:00:00.058363: Finished initializing formals in 0ms.
0:00:00.060115: Computed 1195 combined member signatures in 1ms.
0:00:00.060165: Updated 31 classes in kernel hierarchy in 0ms.
0:00:00.061406: Added noSuchMethod forwarders in 1ms.
0:00:00.061440: Checked mixin declaration applications in 0ms.
0:00:00.074252: Build outline expressions in 12ms.
0:00:00.074299: Checked redirecting factories in 0ms.
0:00:00.076276: Indexed 196 libraries (0 bytes) in 1.971ms, that is,
       0.000 bytes/ms, and
       0.010 ms/libraries.
[INFO] build_web_compilers:ddc on package:web_skin_dart/ui_components/icon.ddc.module:
0:00:00.000065: Started building UriTranslator in 0ms.
0:00:00.003449: Read libraries file in 3ms.
0:00:00.006783: Read packages file in 3ms.
0:00:00.006860: Read packages file in 0ms.
0:00:00.008873: Decided to reuse 184 of 197 libraries in 2ms.
0:00:00.028644: Built outlines for 6 compilation units (60436 bytes) in 19.752ms, that is,
    3059.741 bytes/ms, and
       3.292 ms/compilation unit.
0:00:00.028752: Built outlines for 6 compilation units (60436 bytes) in 0.051ms, that is,
 1185019.608 bytes/ms, and
       0.008 ms/compilation unit.
0:00:00.028936: Resolved parts in 0ms.
0:00:00.028958: Applied patches in 0ms.
0:00:00.029653: Computed library scopes in 0ms.
0:00:00.030401: Resolved 246 types in 0ms.
0:00:00.030451: Computed variances of 0 type variables in 0ms.
0:00:00.030541: Computed default types for 0 type variables in 0ms.
0:00:00.030647: Checked class hierarchy in 0ms.
0:00:00.030667: Checked imports and exports for duplicate names in 0ms.
0:00:00.030691: Resolved 0 type-variable bounds in 0ms.
0:00:00.031387: Built component in 0ms.
0:00:00.031428: Installed Object as implicit superclass in 0ms.
0:00:00.031546: Installed synthetic constructors in 0ms.
0:00:00.031589: Resolved 0 constructors in 0ms.
0:00:00.031789: Linked component in 0ms.
0:00:00.031898: Computed core types in 0ms.
0:00:00.065996: Built class hierarchy in 34ms.
0:00:00.081512: Computed class hierarchy in 15ms.
0:00:00.082440: Performed top level inference in 0ms.
0:00:00.082500: Checked supertypes in 0ms.
0:00:00.083424: Checked type arguments of supers against the bounds in 0ms.
0:00:00.085566: Checked 429 overrides in 2ms.
0:00:00.085607: Finished initializing formals in 0ms.
0:00:00.108603: Computed 4134 combined member signatures in 22ms.
0:00:00.108669: Updated 72 classes in kernel hierarchy in 0ms.
0:00:00.113018: Added noSuchMethod forwarders in 4ms.
0:00:00.113049: Checked mixin declaration applications in 0ms.
0:00:00.125763: Build outline expressions in 12ms.
0:00:00.125801: Checked redirecting factories in 0ms.
0:00:00.126942: Indexed 188 libraries (0 bytes) in 1.139ms, that is,
       0.000 bytes/ms, and
       0.006 ms/libraries.
[INFO] build_web_compilers:ddc on package:user_analytics/src/admin_client_signposts/assigned_roles_dialog_dismiss_event.ddc.module:
0:00:00.000058: Started building UriTranslator in 0ms.
0:00:00.001683: Read libraries file in 1ms.
0:00:00.003858: Read packages file in 2ms.
0:00:00.003900: Read packages file in 0ms.
0:00:00.004247: Decided to reuse 56 of 65 libraries in 0ms.
0:00:12.287727: Built outlines for 1480 compilation units (21062116 bytes) in 12283.474ms, that is,
    1714.671 bytes/ms, and
       8.300 ms/compilation unit.
0:00:12.288127: Built outlines for 1480 compilation units (21062116 bytes) in 0.071ms, that is,
296649521.127 bytes/ms, and
       0.000 ms/compilation unit.
0:00:12.288860: Resolved parts in 0ms.
0:00:12.288981: Applied patches in 0ms.
0:00:12.359194: Computed library scopes in 70ms.
0:00:12.434255: Resolved 225854 types in 75ms.
0:00:12.438330: Computed variances of 0 type variables in 4ms.
0:00:12.478208: Computed default types for 1 type variables in 39ms.
0:00:12.553862: Checked class hierarchy in 75ms.
0:00:12.555887: Checked imports and exports for duplicate names in 1ms.
0:00:12.556713: Resolved 1 type-variable bounds in 0ms.
0:00:12.871046: Built component in 314ms.
0:00:12.881436: Installed Object as implicit superclass in 10ms.
0:00:12.959033: Installed synthetic constructors in 77ms.
0:00:12.967602: Resolved 0 constructors in 8ms.
0:00:12.968882: Linked component in 1ms.
0:00:12.969095: Computed core types in 0ms.
0:00:17.260493: Built class hierarchy in 4291ms.
0:00:17.429217: Computed class hierarchy in 168ms.
0:00:17.454933: Performed top level inference in 25ms.
0:00:17.470302: Checked supertypes in 15ms.
0:00:17.634768: Checked type arguments of supers against the bounds in 164ms.
0:00:17.678472: Checked 24957 overrides in 43ms.
0:00:17.678596: Finished initializing formals in 0ms.
0:00:20.714243: Computed 1039731 combined member signatures in 3035ms.
0:00:20.721496: Updated 21011 classes in kernel hierarchy in 7ms.
0:00:21.268499: Added noSuchMethod forwarders in 546ms.
0:00:21.279761: Checked mixin declaration applications in 11ms.
0:00:21.899443: Build outline expressions in 619ms.
0:00:21.914555: Checked redirecting factories in 15ms.
0:00:22.010144: Indexed 1536 libraries (0 bytes) in 95.561ms, that is,
       0.000 bytes/ms, and
       0.062 ms/libraries.

The build never completed and was stuck on a compile step for 25 min before I killed it 🤷

Presumably to compare with 2.7.2 I'll have to checkout the release commit, and then cherry pick the verbose SDK commit on top of it and then build it... am I understanding that correctly and would that be helpful to do?

smaifullerton-wk on 20 May 2020

Any update on this issue? Is there more that we can do or different information that we can provide?

evanweible-wf on 28 May 2020

Sorry I missed the update on this thread, I can look next week.

Presumably to compare with 2.7.2 I'll have to checkout the release commit, and then cherry pick the verbose SDK commit on top of it and then build it... am I understanding that correctly and would that be helpful to do?

Yes, that would let us compare the more fine grained timing breakdowns to figure out which part is slower (hopefully).

jakemac53 on 29 May 2020

👍1

This is likely unrelated but I did notice in the last section of the logs you pasted, for one of the modules in the user_analytics package, it appears to have compiled 1480 compilation units (files) into one module. Is that expected?

0:00:12.287727: Built outlines for 1480 compilation units (21062116 bytes) in 12283.474ms, that is,
    1714.671 bytes/ms, and
       8.300 ms/compilation unit.

jakemac53 on 1 Jun 2020

@jakemac53 Yeah that is expected for us right now. That package has a bunch of generated analytic definitions in its main entry point. We're in the process of removing that mega entry point that contains all of the definitions in favor of granular ones, but we're stuck with it for a little while longer. But it's nothing new and should be unrelated to this issue like you said.

evanweible-wf on 4 Jun 2020

👍1

I've spent a couple hours trying to get data for 2.7.2 with the verbose option using the same steps as above and am stuck here:

[SEVERE] build_web_compilers:ddc on package:sockjs_client/sockjs_client.ddc.module:
Error creating sockjs_client|lib/sockjs_client.ddc.dill
Error creating kernel summary for module:sockjs_client|lib/sockjs_client.ddc.dill

Response:--dart-sdk-summary=file:///Users/smaifullerton/dart-sdk/sdk/xcodebuild/ReleaseX64/dart-sdk/lib/_internal/ddc_sdk.dill --output=/private/var/folders/0q/4wbj82x928b9cnrwgw2nnr5m0000gn/T/scratch_spaceGzxO3V/packages/sockjs_client/sockjs_client.ddc.dill --packages-file=org-dartlang-app:///.dart_tool/package_config.json --multi-root-scheme=org-dartlang-app --exclude-non-sources --summary-only --target=ddc --libraries-file=file:///Users/smaifullerton/dart-sdk/sdk/xcodebuild/ReleaseX64/dart-sdk/lib/libraries.json --reuse-compiler-result --use-incremental-compiler --used-inputs=/var/folders/0q/4wbj82x928b9cnrwgw2nnr5m0000gn/T/kernel_builder_GsbMTS/used_inputs.txt --source=package:sockjs_client/src/transport/receiver.dart --source=package:sockjs_client/src/transport/websocket.dart --source=package:sockjs_client/src/transport/receiver-xhr.dart --source=package:sockjs_client/src/events.dart --source=package:sockjs_client/sockjs_client.dart --source=package:sockjs_client/src/ajax.dart --source=package:sockjs_client/src/transport/xhr.dart --source=package:sockjs_client/src/info.dart --source=package:sockjs_client/src/transport/polling.dart --source=package:sockjs_client/src/utils.dart --source=package:sockjs_client/src/client.dart --source=package:sockjs_client/src/transport/sender.dart --verbose
org-dartlang-app:///.dart_tool/package_config.json: Error: Problem in packages configuration file: Not a valid package name
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/transport/receiver.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/transport/websocket.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/transport/receiver-xhr.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/events.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/sockjs_client.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/ajax.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/transport/xhr.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/info.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/transport/polling.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/utils.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/client.dart'.
Error: Could not resolve the package 'sockjs_client' in 'package:sockjs_client/src/transport/sender.dart'.
Error: Not found: 'package:sockjs_client/src/transport/receiver.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/transport/websocket.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/transport/receiver-xhr.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/events.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/sockjs_client.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/ajax.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/transport/xhr.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/info.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/transport/polling.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/utils.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/client.dart'
org-dartlang-untranslatable-uri:package%3Asockjs_client%2Fsrc%2Ftransport%2Freceiver.dart: Error: Not found: 'package:sockjs_client/src/transport/sender.dart'
Error: Not found: 'package:dart2_constant/convert.dart'
Error: Not found: 'package:collection/src/empty_unmodifiable_set.dart'
Error: Not found: 'package:typed_data/typed_buffers.dart'
Error: Not found: 'package:term_glyph/src/generated/glyph_set.dart'
Error: Not found: 'package:fixnum/src/int64.dart'
Error: Not found: 'package:cooky/cooky.dart'
Error: Not found: 'package:rxdart/samplers.dart'
Error: Not found: 'package:react/react_dom_server.dart'
Error: Not found: 'package:over_react/src/util/pretty_print.dart'
Error: Not found: 'package:built_value/built_value.dart'
Error: Not found: 'package:js/js_util.dart'
Error: Not found: 'package:workspaces_frugal/workiva_frugal_api_model/f_status.dart'
Error: Not found: 'package:workspaces_frugal/workiva_frugal_api_model/f_health_condition.dart'
Error: Not found: 'package:workspaces_frugal/workspaces_frugal_v4/f_fbs_account_status.dart'
Error: Not found: 'package:wdesk_sdk/src/constants.dart'
Error: Not found: 'package:licensing_frugal/licensing_frugal_v4_common/f_license_definition_type.dart'
Error: Not found: 'package:licensing_frugal/licensing_frugal_v4_context_kind/f_solution_type.dart'
Error: Not found: 'package:w_common/json_serializable.dart'
Error: Not found: 'package:wuri_sdk/src/registry_data.dart'
Error: Not found: 'package:synchronized/src/utils.dart'
Error: Not found: 'package:browser_storage/src/storage_implementations/sync_memory_storage_impl.dart'
Error: Not found: 'package:react/react_client/js_backed_map.dart'
Error: Not found: 'package:w_common/src/common/disposable_state.dart'
Error: Not found: 'package:w_common/w_common.dart'

There were some merge conflicts I had to resolve in bazel_worker.dart with some signatures and which I did as such (again, this is 2.7.2 of the SDK with the --verbose option commit cherry-picked on top of it):

Future<InitializedCompilerState> initializeIncrementalCompiler(
    InitializedCompilerState oldState,
    Set<String> tags,
    Uri sdkSummary,
    Uri packagesFile,
    Uri librariesSpecificationUri,
    List<Uri> summaryInputs,
    Map<Uri, List<int>> workerInputDigests,
    Target target,
    FileSystem fileSystem,
    Iterable<String> experiments,
    bool outlineOnly,
    Map<String, String> environmentDefines,
    {bool trackNeededDillLibraries: false, 
    bool verbose: false}) async {
  List<Component> outputLoadedInputSummaries =
      new List<Component>(summaryInputs.length);

Future<InitializedCompilerState> initializeCompiler(
    InitializedCompilerState oldState,
    Uri sdkSummary,
    Uri librariesSpecificationUri,
    Uri packagesFile,
    List<Uri> summaryInputs,
    List<Uri> linkedInputs,
    Target target,
    FileSystem fileSystem,
    Iterable<String> experiments,
    Map<String, String> environmentDefines, {
      bool verbose: false
    }) async {

@jakemac53 Do you see anything that would cause the errors above from here? ^^ There were a couple add'l parameters that conflicted but they weren't used in these functions (at the time of 2.7.2), so I removed them.

FWIW, over_react is an open source package that has a 1m 9s build time in root with 2.7.2 and 1m 24s with 2.8.4, so maybe you could use that package for investigation?

smaifullerton-wk on 8 Jun 2020

@smaifullerton-wk ah - the problem is likely that the sdk didn't support the new package config format back then. So we would also need to downgrade build_modules and/or build_web_compilers some :/.

jakemac53 on 8 Jun 2020

@jakemac53 do you know which versions of build_* packages we'd need? Smai is out today so I might take a stab at it.

evanweible-wf on 9 Jun 2020

I believe that build_modules 2.8.1 and build_web_compilers 2.9.0 should work

jakemac53 on 10 Jun 2020

Package: over_react

Dart SDK | Real | User | Sys | CPU | Verbose Kernel Logs Link
-----------|------|-------|-------|------|---------------------------
2.7.2 | 1:36 | ~222s | ~30s | 261% | logs
2.9.0-beta | 1:46 | ~306s | ~34s | 320% | logs

Notes:

I picked over_react because it's our largest OSS package and I wanted to demonstrate that there _is_ an increase in build time, even if it's only 10s in this case. That increase is exacerbated in our larger internal packages.
Same number of actions in both cases (11213 actions).
Real elapsed time doesn't increase much, but I'm guessing that's because I have a machine with 32gb RAM.
User time and CPU are all significantly higher on 2.8+

I tried to grok some useful information from comparing the two sets of logs, but I'm not really sure what is expected and what isn't :) One snippet that I found interesting:

2.7.2

[INFO] build_web_compilers:ddc on test/over_react_component_declaration_test.ddc.module:
0:00:00.000042: Started building UriTranslator in 0ms.
0:00:00.001571: Read libraries file in 1ms.
0:00:00.003993: Read packages file in 2ms.
0:00:00.004017: Read packages file in 0ms.
0:00:00.005522: Decided to reuse 353 of 406 libraries in 1ms.
0:00:00.005690: Indexed 329 libraries (0 bytes) in 0.156ms, that is,
       0.000 bytes/ms, and
       0.000 ms/libraries.
0:00:00.200621: Built outlines for 275 compilation units (2585395 bytes) in 194.898ms, that is,
   13265.375 bytes/ms, and
       0.709 ms/compilation unit.

2.9.0-beta

[INFO] build_web_compilers:ddc on test/over_react_component_declaration_test.ddc.module:
0:00:00.000062: Started building UriTranslator in 0ms.
0:00:00.001393: Read libraries file in 1ms.
0:00:00.002874: Read packages file in 1ms.
0:00:00.002934: Read packages file in 0ms.
0:00:00.005715: Decided to reuse 320 of 404 libraries in 2ms.
0:00:00.005951: Indexed 327 libraries (0 bytes) in 0.217ms, that is,
       0.000 bytes/ms, and
       0.001 ms/libraries.
0:00:00.207175: Built outlines for 275 compilation units (2585395 bytes) in 201.176ms, that is,
   12851.409 bytes/ms, and
       0.732 ms/compilation unit.
0:00:00.207269: Built outlines for 275 compilation units (2585395 bytes) in 0.030ms, that is,
86179833.333 bytes/ms, and
       0.000 ms/compilation unit.

Decided to reuse fewer libraries
Built outlines for the same set of compilation units twice instead of just once, although the second time does look to be cached ¯_(ツ)_/¯
Generally, the outline building seems to be just a bit slower than on 2.7.2

@jakemac53 is this helpful? We'd love to get to the bottom of this so we can know whether a fix is possible and decide when to upgrade to 2.8+.

evanweible-wf on 2 Jul 2020

@evanweible-wf Thanks, it is useful.

The problem right now is that we are pushing very hard on enabling the flutter tech preview for NNBD so I have not had the ability to look into it further yet :(.

jakemac53 on 6 Jul 2020

@jakemac53 any idea when this will be able to be looked into? We just saw the email about "Mitigation for DDC bug in Chrome 87" and it looks like we'd need to include that script in all of our apps and browser tests, which isn't ideal. Obviously it'd be better for us to fix by upgrading to the latest SDK (which would also help us avoid similar issues in the future).

evanweible-wf on 8 Sep 2020

I don't know enough about kernel to know what might cause this, but looking at that same module I see this part which appears to have more of an impact:

2.7.2

0:00:00.422399: Checked 5078 overrides in 3ms.
0:00:00.422448: Finished initializing formals in 0ms.
0:00:00.555440: Computed 20195 combined member signatures in 132ms.

2.9.0-beta

0:00:00.985677: Checked 7568 overrides in 10ms.
0:00:00.985745: Finished initializing formals in 0ms.
0:00:01.534222: Computed 156538 combined member signatures in 548ms.

cc @jensjoha do you know why it might need to compute far more member signatures than it used to, or why it checks more overrides? These are both the same module being compiled and most of the other numbers line up exactly (at least in terms of raw # of things being done).

jakemac53 on 8 Sep 2020

It also took it much longer to build the class hierarchy:

2.7.2

0:00:00.396249: Built class hierarchy in 140ms.

2.9.0-beta

0:00:00.926276: Built class hierarchy in 667ms.

jakemac53 on 8 Sep 2020

I think the additional override checks and member signature is because of nnbd stuff... Johnni will probably know more.

/cc @johnniwinther

jensjoha on 9 Sep 2020

Yes. It a natural consequence of the need for building and maintaining both opt-in and opt-out signatures; every time an opt out class extends/implements and opt-in class we need to create synthetic member signatures and these in turn create the need for more checks.

johnniwinther on 9 Sep 2020

Note that there were ~7.5x more combined member signatures that were computed. Is that an expected growth factor?

There was no enabling of NNBD here so this would only apply for SDK types it sounds like? @evanweible-wf do you know if this app is implementing/extending core SDK classes a lot?

jakemac53 on 9 Sep 2020

@evanweible-wf's out today, so I'm filling in with some data collection.

I wrote a small script that analyzes the libraries reachable from the entypoint of our app and counts ClassElements, and here are the results:

| Type | Count |
| --- | ---: |
| ClassElements | 52494 |
| ClassElements that implement Map | 14936 |
| ClassElements that implement Iterable | 123 |

So, 28.7% of our classes and mixins either implement or extend core types 😬.

Of those 14936 that implement Map, most are subclasses of the over_react UiProps class that implements Map, or subclasses of the similar UiState class](https://github.com/Workiva/over_react/blob/master/lib/src/component_declaration/component_base.dart#L408).

Together, those account for all but 38 of the ClassElements that implement Map.

| Type | Count |
| --- | ---: |
| Implements UiProps (total) | 11714 |
| Implements UiProps (user authored) | 3892 |
| Implements UiProps (generated) | 7822 |
| Implements UiState (total) | 3184 |
| Implements UiState (user authored) | 2063 |
| Implements UiState (generated) | 1121 |
| Implements Map but not UiProps/UiState | 38 |

greglittlefield-wf on 9 Sep 2020

Since Object has 5 methods, every simple class in a legacy library will have 5 method signatures. For large interfaces like Iterable and Map it is of course even worse. So ~7.5x growth is expected.

johnniwinther on 10 Sep 2020

Would we expect this to return to the old performance profile once they are also opted in to NNBD?

jakemac53 on 10 Sep 2020

Yes. Then we don't need the member signatures anymore.

johnniwinther on 10 Sep 2020

Ok, I am not sure what action items we can take here then :(. It sounds like this is the likely culprit, although we could do some additional digging to add up the time differences for these steps for all the modules and see if that equals roughly the total time difference to validate things.

I don't know what path forward that really gives you. You could stay on 2.7.x until you are able to migrate to NNBD, although that will likely be quite some time given all the dependencies that over_react has.

jakemac53 on 10 Sep 2020

It does sound to me @johnniwinther like this is re-doing a lot of work (recreating the same synthetic member signatures over and over). I don't know the feasibility of fixing that though.

jakemac53 on 10 Sep 2020

It is, but unfortunately our class hierarchy builder is not currently in a shape that lends itself to optimizations. I am working on getting it in shape but it'll be a while.

johnniwinther on 10 Sep 2020

Would we just need to migrate over_react to NNBD to restore the original build perf for these particular classes? Or will we still take the hit in each of our consuming packages that have classes that implement UiProps and UiState until they're also migrated?

evanweible-wf on 10 Sep 2020

You would be taking a hit for any opted-out class that implements/extends any opted-in class. So you would continue to take a hit until all consumers are migrated. From what I understand this hit would be incurred when compiling any opted out module, so in theory you could slowly gain performance back as you migrate.

jakemac53 on 10 Sep 2020

👍1

Looking further into the numbers I found that the "combined member signatures" is not referring to "member signatures". The "combined member signatures" messages is an old message from before "member signatures" used for opt-in/opt-out boundaries where introduced. What it refers to is the number of members whose types have been computed (think of members with no explicit types). The old implementation didn't properly compute these in dependency order, so sometimes we would try to compute the member signature of a subclass before the member signatures of the superclass on which it depends were computed. In https://dart-review.googlesource.com/c/sdk/+/138294 this was changed to enforce a top-down computation of all member signatures. This means that the number now refers to all members with dependencies. Whether the computation can be sped up is a different matter that I'll look into.

johnniwinther on 12 Sep 2020

@johnniwinther - the other day you mentioned that you landed https://github.com/dart-lang/sdk/commit/c9576a1dac4b155be545ac396e2a532a1208d7e9 - was that intended to speed things up in this scenario?

If so, it would be great to test it out, it may be worth discussing whether it should be considered for 2.10-beta.

If I understand correctly, this change is currently not available on our regular channels, but should be included on the first dev channel release starting with 2.11.0-dev. (@athomas is that correct?)

sigmundch on 25 Sep 2020

It was intended to speed up the computation of "simple" boundaries between opt-in and opt-out classes. It roughly gives a 2x speed up of the computation of these. It is very dependent on the actual class hierarchy what proportion of the computed member signatures that are simple.

johnniwinther on 25 Sep 2020

It does still sound like it would be worth trying out for sure - we have a new dev release now which should contain this 2.11.0-161.0.dev.

jakemac53 on 25 Sep 2020

I have some new information on this - or maybe an additional problem. It seems to be related to hashing during kernel generation.

I tried 2.10, and later bleeding edge versions, and the compile times are much much worse. I managed to get some profile information on DDC (which is a non-trivial task, and not documented) and it was spending 99% of its time computing hashCodes in ClassHierarchyBuilder.registerOverrideDependency, with apparently very large InterfaceConflict objects. The most obvious thing where this was happening was a props property where we had an unnecessary getter being generated in subclasses. And we have classes that have 11 mixins, all of them related. Removing the generation of that property helps a bit, but not entirely.

As a hack, I added a LinearSet class that didn't hash, and replaced the initialization of overriddenMembers and the result in the _toSet method. With that, I can build a package that took 2:49 in 2.7.2 in 3:49 in a bleeding edge from Oct 16. So it seems likely that there are more hashing issues than that one. I suspect this is a combination of our codegen creating inconsequentially different definitions from the originals, (e.g. Map vs Map), that this complicates the analyzer's logic and sends its hashing expontential, and that this is then mixed in repeatedly to a class.

As an indicator, here's a bit of a log message (this one is a compile error, but you get the idea)
'_$$OurClassProps.MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove%MapViewMixin.remove%MapMixin.remove%Map.remove

though I also came across the following definition, where we have things of the form abstract class SomeClassV7 implements SomeClassV6
Combined Member Signature of Object.toString%Object.toString%Object.toString%Object.toString%Object.toString%Object.toString%Object.toString: Object.toString
zCombined Member Signature of Object.toString%Object.toString%Object.toString%Object.toString%Object.toString%Object.toString%Object.toString: new ForwardingNode(ClassBuilder(SomeClassV7), DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), InterfaceConflict(SomeClassV6, [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), InterfaceConflict(SomeClassV5, [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), InterfaceConflict(SomeClassV4, [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), InterfaceConflict(SomeClassV3, [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), InterfaceConflict(SomeClassV2, [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false), InterfaceConflict(SomeClass, [DillClassMember(DillMemberBuilder(Object.toString),forSetter=false)])])])])])])], ProcedureKind.Method)

I will look into a more reproducible example, but maybe this much information would also be useful for the CFE developers.

alanknight-wk on 22 Oct 2020

👍1

@alanknight-wk This is great!

johnniwinther on 23 Oct 2020

Thanks! But it will be better if I can actually narrow down what specific things are causing this. Any suggestions on getting that information out of a build?

alanknight-wk on 23 Oct 2020

So I do have a fix for the hashCode slowness; they are not need for semantics but were added to verify consistency across refactoring, so we can just remove them.

It would be nice to have a repro to verify the regression, though.

These patterns arise in cases where members with the same are declared many times in the same hierarchy. For instance

mixin M0 { int get property; }
mixin M1 implements M0 { int get property; }
mixin M2 implements M1 { int get property; }
mixin M3 implements M2 { int get property; }
abstract class Super {
  int get property;
}
class Class extends Super with M0, M1, M2, M3 {
  int get property => 0;
}

johnniwinther on 23 Oct 2020

I was able to verify that this pattern does indeed exercise the bad behavior.

These are times (ms) for building the hierarchy with n+1 mixins:

n | with equals | without equals
-- | -- | --
10 | 40 | 35
15 | 48 | 37
20 | 197 | 39
25 | 5023 | 39
26 | 9067 | 39
27 | 18707 | 38

johnniwinther on 23 Oct 2020

Ah, right. So, if as in over_react, we had

abstract class UiProps extends MapBase
    with
        MapViewMixin,
        PropsMapViewMixin,
        ReactPropsMixin,
        UbiquitousDomPropsMixin,
        CssClassPropsMixin
    implements Map {

and then components extended that and then typically mixed in multiple different Props classes, e.g.

@Props()
class _$SomethingProps extends SomethingElseProps
    with
        SomeOtherPropsMixin,
        // ignore: mixin_of_non_class, undefined_class
        $SomeOtherPropsMixin {

and ones that looked troublesome had, like 11 different mixins like that, this would probably cause that sort of conflict...

alanknight-wk on 23 Oct 2020

I've created https://dart-review.googlesource.com/c/sdk/+/168942 for this

johnniwinther on 23 Oct 2020

Woohoo! With that patch applied, 2:56 to build the package that took 2:49 in 2.7.2, so basically within random variation. Thank you Johnni!

alanknight-wk on 23 Oct 2020

🚀2 🎉1 👍1

I'll close this issue, assuming we've fixed the root cause. If we still see regressions we should reopen this issue or create a new.

johnniwinther on 8 Nov 2020

👍1

Build: DDC build time regression on Dart 2.8.1

Most helpful comment

All 65 comments

[#].apply(#, #)

Related issues