pub run "hello world" takes 2.5 seconds

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="96" height="96"hspace="10"> Issue by sethladd
Originally opened as dart-lang/sdk#20212

---

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]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment 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]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment 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.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment by sethladd

---

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

[DartBot]

<img src="https://avatars.githubusercontent.com/u/188?v=3" align="left" width="48" height="48"hspace="10"> Comment by nex3

---

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

---

Added NotPlanned label.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment by sethladd

---

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

---

Added Waiting label.
Marked this as being blocked by dart-lang/sdk#16368.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment by sethladd

---

Curious, why does pub run spawn git?

Spawning "git --version"

[DartBot]

<img src="https://avatars.githubusercontent.com/u/188?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment 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?

[DartBot]

<img src="https://avatars.githubusercontent.com/u/188?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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;.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment by sethladd

---

To repro:

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

[DartBot]

<img src="https://avatars.githubusercontent.com/u/22043?v=3" align="left" width="48" height="48"hspace="10"> Comment by skabet

---

Turns out there are more things to it, than issue dart-lang/sdk#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.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/46275?v=3" align="left" width="48" height="48"hspace="10"> Comment by munificent

---

Thanks for hacking on this, Anders!

[DartBot]

<img src="https://avatars.githubusercontent.com/u/22043?v=3" align="left" width="48" height="48"hspace="10"> Comment by skabet

---

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/

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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?

[DartBot]

<img src="https://avatars.githubusercontent.com/u/46275?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/5449880?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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]

<img src="https://avatars.githubusercontent.com/u/5479?v=3" align="left" width="48" height="48"hspace="10"> Comment by sethladd

---

What's reasonable by 1.6, do we reckon?

[DartBot]

<img src="https://avatars.githubusercontent.com/u/46275?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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.

[DartBot]

<img src="https://avatars.githubusercontent.com/u/46275?v=3" align="left" width="48" height="48"hspace="10"> Comment by 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.