pub run "hello world" takes 2.5 seconds

[DartBot]

This issue was originally filed by @sethladd

---

Hi,

Just testing out pub run. On my macbook air, running Dart 1.6, and running a "hello world" script, it's taking 2.5 seconds. That seems long for a simple script.

~/WebstormProjects/stagehand$ dart --version
Dart VM version: 1.6.0-dev.4.0 (Fri Jul 18 06:17:25 2014) on "macos_x64"

~/WebstormProjects/stagehand$ time pub run stagehand
I'll turn it up to 11.

real 0m2.542s
user 0m2.000s
sys 0m0.368s

~/WebstormProjects/stagehand$ cat bin/stagehand.dart
main() {
  print("I'll turn it up to 11.");
}

For reference, here's a raw run:

~/WebstormProjects/stagehand$ time dart bin/stagehand.dart
I'll turn it up to 11.

real 0m0.091s
user 0m0.073s
sys 0m0.016s

[DartBot]

This comment was originally written by @sethladd

---

I guess this is because there's transformers infrastructure that needs to get booted up? Note there are no transformers configured, here's the pubspec.yaml:

name: stagehand
version: 0.0.1
dev_dependencies:
  unittest: any

Not sure why, but it appears to be spawning up git version ?

~/WebstormProjects/stagehand$ pub run -v stagehand
FINE: Pub 1.6.0-dev.4.0
FINE: Loaded package graph.
FINE: Initializing barback...
FINE: Serving packages on localhost:0.
MSG : Loading source assets...
FINE: Providing sources for stack_trace|lib.
IO : Spawning "git --version" in /Users/sethladd/WebstormProjects/stagehand/.
IO : Finished git. Exit code 0.
    | stdout:
    | | git version 1.7.4.4
    | Nothing output on stderr.
FINE: Determined git command null.
FINE: Providing sources for matcher|lib.
FINE: Providing sources for unittest|lib.
FINE: Providing sources for path|lib.
FINE: Providing sources for stagehand|lib.
FINE: Loading source assets finished (1.6s).
FINE: Provided sources.
FINE: Loading transformers...
FINE: Transformer dependencies:
FINE: Loading transformers finished (0.3s).
FINE: Initializing barback finished (2.1s).
FINE: Providing sources for stagehand|bin.
FINE: Bound "bin" to localhost:0.

[DartBot]

This comment was originally written by @sethladd

---

FWIW it seems to be a little quicker via pub global:

~/WebstormProjects/stagehand[master]$ time pub global run stagehand
I'll turn it up to 11.

real 0m2.064s
user 0m1.924s
sys 0m0.346s

Not sure why. Here's the log:

~/WebstormProjects/stagehand[master]$ pub global run -v stagehand
FINE: Pub 1.6.0-dev.4.0
FINE: Loaded package graph.
FINE: Initializing barback...
FINE: Serving packages on localhost:0.
MSG : Loading source assets...
FINE: Providing sources for stack_trace|lib.
IO : Spawning "git --version" in /Users/sethladd/WebstormProjects/stagehand/.
IO : Finished git. Exit code 0.
    | stdout:
    | | git version 1.7.4.4
    | Nothing output on stderr.
FINE: Determined git command null.
FINE: Providing sources for matcher|lib.
FINE: Providing sources for unittest|lib.
FINE: Providing sources for path|lib.
FINE: Providing sources for stagehand|lib.
FINE: Loading source assets finished (1.3s).
FINE: Provided sources.
FINE: Loading transformers...
FINE: Transformer dependencies:
FINE: Loading transformers finished (0.3s).
FINE: Initializing barback finished (1.8s).
FINE: Providing sources for stagehand|bin.
FINE: Bound "bin" to localhost:0.
I'll turn it up to 11.

[sethladd]

Removed Priority-Unassigned label.
Added Priority-Medium, Area-Pub, Triaged labels.

[nex3]

The vast majority of this time is being spent working around issue #16368. I don't think it's worth worrying about how to speed this up until that's fixed.

---

Added NotPlanned label.

[sethladd]

When 16368 is fixed, it will fix this. I've linked the two issues.

---

Added Waiting label.
Marked this as being blocked by #16368.

[sethladd]

Curious, why does pub run spawn git?

Spawning "git --version"

[nex3]

Curious, why does pub run spawn git?

If it's run within a git project, pub uses "git ls-files" to determine which files are part of the project.

[DartBot]

This comment was originally written by @sethladd

---

AFAIU pub global only works with packages from pub.dartlang.org (at least, that's what we've been told to document).

I see that my local pub global run is spawning git. Should it not do that?

[nex3]

Eventually it will work with path and git dependencies as well. We could add some code to avoid even trying git for hosted packages, but until we have evidence that git is actually causing performance problems I don't think it's worthwhile;.

[sethladd]

To repro:

Go to http://pub.dartlang.org/packages/simple_http_server and follow the instructions for install and use. :)

[andersjohnsen]

Turns out there are more things to it, than issue #16368.

Suggested CLs so far:

https://codereview.chromium.org/429173002/
https://codereview.chromium.org/420063003/

While these fixes alone will not bring it down to a acceptable level, this is a good start. I'll continue to investigate, as these improvements will help other pub commands and packages as well.

---

Set owner to @Skabet.
Added Started label.

[munificent]

Thanks for hacking on this, Anders!

[andersjohnsen]

Committed one of the previous CLs so far.

Created a few other CLs for this:

https://codereview.chromium.org/439223002/
https://codereview.chromium.org/444583003/

[sethladd]

Thanks! What's a good exit criteria for this issue, so we know when to close? 500ms for a "hello world" ? Can we do better?

[munificent]

On my tests, the VM takes >100ms just to load and compile pub before it even hits main(). I would love to get that number down, but that's obviously out of our control.

It also takes something (very roughly!) around 50ms to spawn the second process.

But, beyond those hits, we should be able to make a lot of progress. I'll be OK if we can get a hello world that doesn't use any transformers down to 200ms. That will require a lot of work, though. We have ideas in mind on what do to here, but haven't set aside time for them this quarter.

I won't be delighted unless we can get it down to <100ms.

---

cc @iposva-google.
cc @turnidge.

[iposva-google]

It also takes something (very roughly!) around 50ms to spawn the second process.
Request for clarification: Second process or isolate?
If process, what is this process running? If isolate, are you spawning a function or a URI?

[DartBot]

This comment was originally written by @sethladd

---

What's reasonable by 1.6, do we reckon?

[munificent]

Request for clarification: Second process or isolate?

Process. We're considering using an isolate but that affects the behavior in some user visible ways. (For example, Platform.script would now return pub's script instead of their own.)

If process, what is this process running?

The user's application. The basic idea is that the user does "pub run foo". Pub starts up, runs all of the appropriate transformers and then runs bin/foo.dart (using an HTTP URL that points back to pub's own server) so that the process can load transformed Dart code. The spawned process is for that application.

[munificent]

What's reasonable by 1.6, do we reckon?

1.6 is very soon, isn't it? I don't think we'll have any significant optimization in by then.

I did do a little profiling today and I think if my idea for routing around barback for packages that don't use transformers works, it should shave off a chunk of the time. On my hacked up test case, it went from ~1.5s to ~1.15s.

[DartBot]

This issue has been moved to dart-lang/pub#1063.