[WIP, DO NOT MERGE] Use fastwalk from goimports #588

ascandella · 2017-05-16T21:42:20Z

References #419 at the request of @sdboyer in Slack.

The fastwalk code is imported as-is from golang/go, and then I added a mutex to protect the shared state.

davecheney · 2017-05-16T23:11:37Z

I would like to see a benchmark included with this PR.

davecheney · 2017-05-16T23:13:13Z

internal/gps/pkgtree/pkgtree.go

@@ -64,17 +65,15 @@ func ListPackages(fileRoot, importRoot string) (PackageTree, error) {
 		ImportRoot: importRoot,
 		Packages:   make(map[string]PackageOrErr),
 	}
+	mu := &sync.Mutex{}


var mu sync.Mutex

sure, is there a style guide for this project? i know many people have different opinions. i'll change this one

ascandella · 2017-05-16T23:46:29Z

Before:

pkgtree - test-bench! ❯ go test -bench=. -benchmem
BenchmarkListPackages-4             2000           1245467 ns/op          215346 B/op       1263 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      2.626s

After:

pkgtree - fastwalk ❯ go test -bench=. -benchmem
BenchmarkListPackages-4             2000           1267992 ns/op          142744 B/op       1171 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      2.675s

So, no significant changes :(

dcheney-atlassian · 2017-05-16T23:48:10Z

So, no significant changes :(

Let's do some profiling then and figure out where the bottleneck is.

ascandella · 2017-05-16T23:50:16Z

It's also possible (probable?) that the cases we have in _testdata are so small that walking the file tree isn't where we're spending much time. I guess I could do a bench on the whole dep tree?

ascandella · 2017-05-16T23:58:50Z

Benched on the whole dep tree, appears fastwalk is slower:

Old:

pkgtree - bench-dep! ❯ go test -bench=. -benchmem -benchtime=5s
BenchmarkListPackages-4              500          17995996 ns/op         4049772 B/op      19074 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      10.810s

New:

pkgtree - fastwalk ❯ go test -bench=. -benchmem -benchtime=5s
BenchmarkListPackages-4              300          23751257 ns/op         6050304 B/op      31457 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      9.620s

ascandella · 2017-05-17T00:06:49Z

Clickable SVGs from go-torch:

Old: https://sca.ndella.com/old.svg

New: https://sca.ndella.com/new.svg

sdboyer · 2017-05-17T00:19:56Z

Yep, looks like it's the filepath.Glob() and the stat we just added that are eating most of the gains. It strikes me that both of those should be unnecessary, now. Lemme sketch that out...

ascandella · 2017-05-17T00:22:46Z

Sounds good. The bench-dep branch is pushed to my personal repo which is head of master + the benchmark for the dep repo. This branch has the same benchmark, but with the fastwalk change.

sdboyer · 2017-05-17T00:27:19Z

Something like this...

Move a bit of the logic from the walkFn up into the fastwalker - it should only be called for directories (DT_DIR).
When it's called, pass it a slice of name + os.FileMode tuples that represent only the files/DT_REG - we know, at least for now, that we're not touching symlinks.
Refactor fillPackages to receive that tuple slice. That should obviate the need for both the glob and that initial stat.

his branch has the same benchmark, but with the fastwalk change.

Excellent - we definitely can't introduce this amount of complexity without benchmarks to justify it.

ascandella · 2017-05-17T00:54:38Z

Cool, I'm done for the day, I'll take a look at optimizing this tomorrow.

ascandella · 2017-05-18T22:47:06Z

Hmm, I've been playing around with various refactors for a while now but keep getting chicken-and-egged as far as having directory listings ready with the directory name. Going to keep thinking on this.

davecheney · 2017-05-18T23:05:35Z

Before you invest more time in this, is it worth profiling dep to determine if there is a bottleneck, and where it is?

…

On Fri, 19 May 2017, 08:47 Aiden Scandella ***@***.***> wrote: Hmm, I've been playing around with various refactors for a while now but keep getting chicken-and-egged as far as having directory listings ready with the directory name. Going to keep thinking on this. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#588 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA6ujjvIGIbmWy4Z3iUVfMKr-FkWpks5r7MpqgaJpZM4NdHef> .

ascandella · 2017-05-18T23:22:23Z

Ya, I'm new to this project, this was just a task @sdboyer said was worth investigating. It may not be worth the effort, but I'm not really in the best position to say. Do we currently have end-to-end benchmarks on what "typical" behavior should be?

jmank88 · 2017-05-19T00:40:35Z

Do we currently have end-to-end benchmarks on what "typical" behavior should be?

I started in that direction with benchmarks in #558, but the existing test cases aren't particularly interesting. More complex integration test cases would be neat, or maybe an alternative way to run or compile the dep cmd to dump timing and profile info. The latter might be more broadly useful, especially for investigating cases in the wild (e.g. "Why is dep so slow on my project?" "Run it again with the '-foo' flag to dump profile info and we'll find out"). I've been meaning to look into this more and write something up.

ascandella · 2017-05-20T19:08:29Z

I recompiled dep with runtime/pprof as so:

dep - master! ❯ git --no-pager diff
diff --git i/cmd/dep/main.go w/cmd/dep/main.go
index ae4cf3a..306f810 100644
--- i/cmd/dep/main.go
+++ w/cmd/dep/main.go
@@ -10,8 +10,10 @@ import (
        "flag"
        "fmt"
        "io"
+       "io/ioutil"
        "log"
        "os"
+       "runtime/pprof"
        "strings"
        "text/tabwriter"

@@ -29,6 +31,13 @@ type command interface {
 }

 func main() {
+       fn, err := ioutil.TempFile("", "pprof")
+       if err != nil {
+               panic(err)
+       }
+       fmt.Println("PProf: fn", fn.Name())
+       pprof.StartCPUProfile(fn)
+
        wd, err := os.Getwd()
        if err != nil {
                fmt.Fprintln(os.Stderr, "failed to get working directory", err)
@@ -41,7 +50,9 @@ func main() {
                WorkingDir: wd,
                Env:        os.Environ(),
        }
-       os.Exit(c.Run())
+       code := c.Run()
+       pprof.StopCPUProfile()
+       os.Exit(code)
 }

Looks like a lot of time spent in crypto/loadSystemRoots

The flame graph is here (you can click in to select segments): https://sca.ndella.com/zap-dep-init.svg -- you can see about 20% of the time is spent in gps.solve of which almost all is listPackages. This is from running dep init -v on github.com/uber-go/zap:

PProf: fn /var/folders/b3/pnm730v50fg2ms_mtbrxkzwc0000gn/T/pprof612691900
dep: Finding dependencies for "github.com/uber-go/zap"...
dep: Found 9 dependencies.
Searching GOPATH for projects...
dep: Building dependency graph...
dep: Found import of "github.com/Sirupsen/logrus", analyzing...
  Using ^0.8.7 as constraint for direct dep github.com/Sirupsen/logrus
  Locking in v0.8.7 (418b41d) for direct dep github.com/Sirupsen/logrus
dep: Found import of "github.com/apex/log", analyzing...
dep: Could not determine version for "github.com/apex/log", omitting from generated manifest
dep: Found import of "github.com/go-kit/kit/log", analyzing...
dep: Could not determine version for "github.com/go-kit/kit", omitting from generated manifest
dep: Found import of "github.com/stretchr/testify/assert", analyzing...
  Using e3a8ff8 as hint for direct dep github.com/stretchr/testify
dep: Found import of "github.com/uber-common/bark", analyzing...
  Using d52ffa0 as hint for direct dep github.com/uber-common/bark
dep: Found import of "github.com/uber-go/atomic", analyzing...
  Using master as constraint for direct dep github.com/uber-go/atomic
  Locking in master (9e99152) for direct dep github.com/uber-go/atomic
dep: Found import of "gopkg.in/inconshreveable/log15.v2", analyzing...
dep: Could not determine version for "gopkg.in/inconshreveable/log15.v2", omitting from generated manifest
dep: Analyzing transitive imports...
dep: Analyzing "github.com/Sirupsen/logrus"...
dep: Analyzing "github.com/apex/log/handlers/json"...
dep: Analyzing "github.com/stretchr/testify/assert"...
dep: Analyzing "github.com/davecgh/go-spew/spew"...
  Locking in  (5215b55) for transitive dep github.com/davecgh/go-spew
dep: Analyzing "github.com/pmezard/go-difflib/difflib"...
  Locking in  (e8554b8) for transitive dep github.com/pmezard/go-difflib
dep: Analyzing "github.com/stretchr/testify/require"...
dep: Analyzing "github.com/uber-common/bark"...
dep: Analyzing "github.com/cactus/go-statsd-client/statsd"...
  Locking in  (dc93b85) for transitive dep github.com/cactus/go-statsd-client
dep: Analyzing "gopkg.in/inconshreveable/log15.v2"...
dep: Analyzing "github.com/apex/log"...
dep: Analyzing "github.com/go-kit/kit/log"...
dep: Analyzing "github.com/uber-go/atomic"...
Using network for remaining projects...
dep: Solving...
Root project is "github.com/uber-go/zap"
 7 transitively valid internal packages
 9 external packages imported from 7 projects
(0)   ✓ select (root)
(1)     ? attempt github.com/Sirupsen/logrus with 1 pkgs; at least 1 versions to try
(1)         try github.com/Sirupsen/[email protected]
(1)     ✓ select github.com/Sirupsen/[email protected] w/1 pkgs
(2)     ? attempt github.com/stretchr/testify with 2 pkgs; at least 1 versions to try
(2)         try github.com/stretchr/testify@e3a8ff8ce36581f87a15341206f205b1da467059
(2)     ✓ select github.com/stretchr/testify@e3a8ff8ce36581f87a15341206f205b1da467059 w/2 pkgs
(3)     ? attempt github.com/davecgh/go-spew with 1 pkgs; at least 1 versions to try
(3)         try github.com/davecgh/go-spew@5215b55f46b2b919f50a1df0eaa5886afe4e3b3d
(3)     ✓ select github.com/davecgh/go-spew@5215b55f46b2b919f50a1df0eaa5886afe4e3b3d w/1 pkgs
(4)     ? attempt gopkg.in/inconshreveable/log15.v2 with 1 pkgs; 12 versions to try
(4)         try gopkg.in/inconshreveable/[email protected]
(4)     ✓ select gopkg.in/inconshreveable/[email protected] w/3 pkgs
(5)     ? attempt github.com/pmezard/go-difflib with 1 pkgs; at least 1 versions to try
(5)         try github.com/pmezard/go-difflib@e8554b8641db39598be7f6342874b958f12ae1d4
(5)     ✓ select github.com/pmezard/go-difflib@e8554b8641db39598be7f6342874b958f12ae1d4 w/1 pkgs
(6)     ? attempt github.com/apex/log with 2 pkgs; 1 versions to try
(6)         try github.com/apex/log@master
(6)     ✓ select github.com/apex/log@master w/2 pkgs
(7)     ? attempt github.com/uber-go/atomic with 1 pkgs; at least 1 versions to try
(7)         try github.com/uber-go/atomic@master
(7)     ✓ select github.com/uber-go/atomic@master w/1 pkgs
(8)     ? attempt github.com/go-kit/kit with 1 pkgs; 10 versions to try
(8)         try github.com/go-kit/[email protected]
(8)     ✓ select github.com/go-kit/[email protected] w/1 pkgs
(9)     ? attempt github.com/uber-common/bark with 1 pkgs; at least 1 versions to try
(9)         try github.com/uber-common/bark@d52ffa061726911f47fcd3d9e8b9b55f22794772
(9)     ✓ select github.com/uber-common/bark@d52ffa061726911f47fcd3d9e8b9b55f22794772 w/1 pkgs
(10)  ? attempt github.com/cactus/go-statsd-client with 1 pkgs; at least 1 versions to try
(10)      try github.com/cactus/go-statsd-client@dc93b8587d799a204e96175505fff9678a8ec3e1
(10)  ✓ select github.com/cactus/go-statsd-client@dc93b8587d799a204e96175505fff9678a8ec3e1 w/1 pkgs
(11)  ? attempt github.com/go-logfmt/logfmt with 1 pkgs; 5 versions to try
(11)      try github.com/go-logfmt/[email protected]
(11)  ✓ select github.com/go-logfmt/[email protected] w/1 pkgs
(12)  ? attempt github.com/kr/logfmt with 1 pkgs; 2 versions to try
(12)      try github.com/kr/logfmt@master
(12)  ✓ select github.com/kr/logfmt@master w/1 pkgs
(13)  ? attempt github.com/go-stack/stack with 1 pkgs; 12 versions to try
(13)      try github.com/go-stack/[email protected]
(13)  ✓ select github.com/go-stack/[email protected] w/1 pkgs
(14)  ? attempt github.com/pkg/errors with 1 pkgs; 11 versions to try
(14)      try github.com/pkg/[email protected]
(14)  ✓ select github.com/pkg/[email protected] w/1 pkgs
(15)  ? attempt github.com/mattn/go-colorable with 1 pkgs; 9 versions to try
(15)      try github.com/mattn/[email protected]
(15)  ✓ select github.com/mattn/[email protected] w/1 pkgs
(16)  ? attempt github.com/mattn/go-isatty with 1 pkgs; 4 versions to try
(16)      try github.com/mattn/[email protected]
(16)  ✓ select github.com/mattn/[email protected] w/1 pkgs
(17)  ? attempt golang.org/x/sys with 1 pkgs; 1 versions to try
(17)      try golang.org/x/sys@master
(17)  ✓ select golang.org/x/sys@master w/1 pkgs
  ✓ found solution with 21 packages from 17 projects

Solver wall times by segment:
              b-gmal: 3.506980319s
         b-list-pkgs: 3.144245245s
     b-source-exists: 1.106882088s
     b-list-versions: 332.315608ms
  b-deduce-proj-root: 125.590738ms
             satisfy:   3.875204ms
         select-atom:   2.641545ms
         select-root:     689.64µs
            new-atom:    584.485µs
               other:     76.106µs

  TOTAL: 8.223880978s

  Using ^0.4.0 as constraint for direct dep github.com/go-kit/kit
  Locking in v0.4.0 (fadad6f) for direct dep github.com/go-kit/kit
  Locking in v1.5.3 (7a2f196) for transitive dep github.com/go-stack/stack
  Locking in v0.0.2 (fc9e8d8) for transitive dep github.com/mattn/go-isatty
  Using ^2.11.0 as constraint for direct dep gopkg.in/inconshreveable/log15.v2
  Locking in v2.11 (b105bd3) for direct dep gopkg.in/inconshreveable/log15.v2
  Locking in v0.3.0 (390ab79) for transitive dep github.com/go-logfmt/logfmt
  Locking in v0.8.0 (645ef00) for transitive dep github.com/pkg/errors
  Using master as constraint for direct dep github.com/apex/log
  Locking in master (7259ed7) for direct dep github.com/apex/log
  Locking in v0.0.7 (d228849) for transitive dep github.com/mattn/go-colorable
  Locking in master (a2e06a1) for transitive dep golang.org/x/sys
  Locking in master (b84e30a) for transitive dep github.com/kr/logfmt
Old vendor backed up to /Users/aiden/src/go/src/github.com/uber-go/zap/vendor-20170518163154
dep: Writing manifest and lock files.

sdboyer · 2017-05-21T03:33:06Z

Before you invest more time in this, is it worth profiling dep to determine
if there is a bottleneck, and where it is?

Definitely, always the prerequisite question. There were a buncha things that led me to suggesting this as an area we might investigate optimizing, though the most bottom-bedrock numbers are actually ones done by @bradfitz in comparing goimports' performance against plain filepath.Walk(), in the context of a discussion about (I think) guru. Or maybe gomvpkg. Something that Alan works on. Unfortunately, I can't remember exactly where I saw it. IIRC, the logic we're working on incorporating here cut running time on large trees by...half? idk. Something nontrivial.

However, teasing out just how significant that is for dep can be hard; indeed, @jmank88's first pass at some benchmarks demonstrate how tricky benchmarking can be here. So, I figure it's probably useful for me to lay out some organizing principles that may be helpful both here, and in constructing benchmarks more generally.

First, the FAQ has some useful background.
For now, the performance issues we care about are the low-n, high-k factors; there's another set of considerations related to the actual cost of purely in-memory solving, when the solver goes exponential. That's a wholly different class of problem; this issue is really about reducing k, not reducing n.
There are five main classes of ops that we do with high k, all ultimately because they involve IO. General metrics on these are dumped in -v output under the Solver wall times by segment: header. Almost all of these are cacheable, many permanently so.
1. SourceManager.ListVersions(), which retrieves a current list of available versions from an upstream source (generally network IO)
2. SourceManager.ListPackages(), which statically analyzes a go code tree, and is the focus of this issue (disk IO)
3. SourceManager.GetManifestAndLock(), which reads in the contents of e.g. Gopkg.toml and Gopkg.lock (disk IO)
4. SourceManager.DeduceProjectRoot() can trigger go get HTTP metadata retrieval (network IO)
5. SourceManager.ExportProject(), which writes out a copy of a project at a given version to an arbitrary location (disk IO)
There are three main phases for each dep command; they must occur serially (though earlier phases can sometimes initialize work in the background for later ones). The current high costs in each area are mostly constituted from one of the preceding five types of IO.
1. Initial project scan
2. Solving
3. Writing out vendor/

Describing these in the reverse of the order in which they actually occur is the best way to have them make sense.

Writing out vendor/ is mostly separate from the others; for now, we just sloppily reconstruct an entire vendor dir from scratch out of the source cache. Once #121 is implemented, we'll have the opportunity to make this more sophisticated. This phase is generally, though not entirely, what happens with the gps.Solution returned from a gps.Solver.Solve() call.

The solving phase is everything under gps.Solver.Solve(), which can include an enormous number of calls to each the OI types 1-4. However, once #431 is implemented and we're storing such results permanently, these costs amortize to zero.

The initial phase is the most varied and complicated. For the purposes of this issue, though, what really matters is that ListPackages() must be called in order to construct the local package list. And, because the current project is the code that's subject to change, there's little point in caching it a la #431 (in fact, the API is designed such that doing so is nigh-impossible). Consequently, literally every single dep run will need to run this code in order to scan the current project; for no-op runs (i.e., input hashes match, so no need for phases 2 and 3), I believe this ListPackages() logic will be almost entirely determinative of the minimum running time.

(BTW, @jmank88, this "initial loading" cost is probably one good area to focus some benchmarks on.)

So: once persistent caching is in place, this scan is likely to become one of if not the largest consistent bottleneck in the program. And it's still worth working on now, because it's a considerable part of the bottleneck we currently see, as well.

bradfitz · 2017-05-21T04:24:28Z

Unfortunately, I can't remember exactly where I saw it

Maybe you're thinking of golang/go#16399

sdboyer · 2017-05-21T11:26:05Z

My vague recollection is seeing it in a discussion that was more specifically comparing it against guru/gomvpkg/something Alan works on. But it doesn't really matter, as golang/go#16399 is definitely dealing with the same underlying problem, and is more exhaustive than what I remember seeing. Thanks for the pointer!

ascandella · 2017-05-21T18:36:45Z

Wow, Sam, your thorough explanations are quite helpful and thoughtful! Thanks for that.

I'm definitely convinced that this path needs optimizing, I think I just need to work on a cleanroom implementation rather than trying to retrofit it into the existing structure. Hopefully I will have time to do that this week.

ascandella · 2017-05-23T22:37:55Z

I haven't forgetten about this, just been sick. Hopefully will be able to resume work tomorrow

sdboyer · 2017-05-24T01:57:51Z

no worries, thanks for update 😄

sdboyer · 2017-05-24T01:57:57Z

feel better!

sdboyer · 2017-05-31T03:16:19Z

bump, just checking in

ascandella · 2017-05-31T15:43:55Z

yo, I am alive and back from sickness/vacation, will look at this again today

ascandella · 2017-06-03T00:48:09Z

Going to have to abandon this for now -- I just switched teams and no longer have free time to work on dep. I may re-open if nobody else picks this up, but that would be in the 2-3 week timeframe :(

sdboyer · 2017-06-03T03:12:20Z

😢 understood - thanks for the clear communication and not just leaving it sit!

googlebot added the cla: yes label May 16, 2017

davecheney reviewed May 16, 2017

View reviewed changes

ascandella changed the title ~~[DO NOT MERGE] Use fastwalk from goimports~~ Use fastwalk from goimports May 16, 2017

ascandella changed the title ~~Use fastwalk from goimports~~ [WIP, DO NOT MERGE] Use fastwalk from goimports May 22, 2017

ascandella added 2 commits May 31, 2017 08:47

Use fastwalk from goimports

1e0972c

Fix race by introducing local err

8c886c5

ascandella added 3 commits May 31, 2017 08:47

Style updates per dcheney

07cd3a2

Add benchmark

8b92f98

Update benchmark

bcf8f9b

ascandella force-pushed the fastwalk branch from be9cb19 to bcf8f9b Compare May 31, 2017 15:47

ascandella closed this Jun 3, 2017

sdboyer mentioned this pull request Aug 15, 2017

WIP: HashFromNode and VerifyDepTree #959

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP, DO NOT MERGE] Use fastwalk from goimports #588

[WIP, DO NOT MERGE] Use fastwalk from goimports #588

ascandella commented May 16, 2017 •

edited

Loading

davecheney commented May 16, 2017

davecheney May 16, 2017

ascandella May 16, 2017

ascandella commented May 16, 2017

dcheney-atlassian commented May 16, 2017

ascandella commented May 16, 2017

ascandella commented May 16, 2017

ascandella commented May 17, 2017

sdboyer commented May 17, 2017

ascandella commented May 17, 2017

sdboyer commented May 17, 2017

ascandella commented May 17, 2017

ascandella commented May 18, 2017

davecheney commented May 18, 2017 via email

ascandella commented May 18, 2017

jmank88 commented May 19, 2017 •

edited

Loading

ascandella commented May 20, 2017 •

edited

Loading

sdboyer commented May 21, 2017 •

edited

Loading

bradfitz commented May 21, 2017

sdboyer commented May 21, 2017

ascandella commented May 21, 2017

ascandella commented May 23, 2017

sdboyer commented May 24, 2017

sdboyer commented May 24, 2017

sdboyer commented May 31, 2017

ascandella commented May 31, 2017

ascandella commented Jun 3, 2017

sdboyer commented Jun 3, 2017

[WIP, DO NOT MERGE] Use fastwalk from goimports #588

[WIP, DO NOT MERGE] Use fastwalk from goimports #588

Conversation

ascandella commented May 16, 2017 • edited Loading

davecheney commented May 16, 2017

davecheney May 16, 2017

Choose a reason for hiding this comment

ascandella May 16, 2017

Choose a reason for hiding this comment

ascandella commented May 16, 2017

dcheney-atlassian commented May 16, 2017

ascandella commented May 16, 2017

ascandella commented May 16, 2017

ascandella commented May 17, 2017

sdboyer commented May 17, 2017

ascandella commented May 17, 2017

sdboyer commented May 17, 2017

ascandella commented May 17, 2017

ascandella commented May 18, 2017

davecheney commented May 18, 2017 via email

ascandella commented May 18, 2017

jmank88 commented May 19, 2017 • edited Loading

ascandella commented May 20, 2017 • edited Loading

sdboyer commented May 21, 2017 • edited Loading

bradfitz commented May 21, 2017

sdboyer commented May 21, 2017

ascandella commented May 21, 2017

ascandella commented May 23, 2017

sdboyer commented May 24, 2017

sdboyer commented May 24, 2017

sdboyer commented May 31, 2017

ascandella commented May 31, 2017

ascandella commented Jun 3, 2017

sdboyer commented Jun 3, 2017

ascandella commented May 16, 2017 •

edited

Loading

jmank88 commented May 19, 2017 •

edited

Loading

ascandella commented May 20, 2017 •

edited

Loading

sdboyer commented May 21, 2017 •

edited

Loading