Adding new dependency logging #194

xmattstrongx · 2017-01-29T19:14:15Z

googlebot · 2017-01-29T19:14:19Z

Thanks for your pull request. It looks like this may be your first contribution to a Google open source project. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please visit https://cla.developers.google.com/ to sign.

Once you've signed, please reply here (e.g. I signed it!) and we'll verify. Thanks.

If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
If you signed the CLA as a corporation, please let us know the company's name.

xmattstrongx · 2017-01-29T19:29:37Z

I signed it!

googlebot · 2017-01-29T19:29:38Z

CLAs look good, thanks!

sdboyer · 2017-01-29T19:33:05Z

cmd/dep/init.go

+			}()
+
+			select {
+			case m := <-message:


I'm not sure it's necessary to print results from the main goroutine. Doing so ends up serializing all the network calls, because the loop can't move on to the next local dep to scan until the syncSourceFor call completes.

Maybe instead, make a closure at the beginning of getProjectData() that we can invoke in a goroutine every time we encounter a new project root.

Of course, we'll need to take some care there to deal with printing from multiple goroutines - if nothing else, it might be better to print only either before or after SyncSourceFor completes.

Ok doing so has increased speed drastically. Though the way Ive written it not sure it needs to be a closure. Im still analyzing the code to make sure the new goroutine to call the closure always has a chance to complete.

sdboyer · 2017-01-29T19:33:35Z

cmd/dep/init.go

+			go func() {
+				goStart := time.Now()
+				defer fmt.Fprintf(os.Stderr, "Go Duration: %s\n", time.Since(goStart))
+				err2 := sm.SyncSourceFor(gps.ProjectIdentifier{ProjectRoot: pr})


As noted in slack, I probably need to add an sm method that more accurately reports the existence of the repo - does it exist upstream? what about on disk?

sdboyer · 2017-01-30T03:04:06Z

cmd/dep/init.go

@@ -265,7 +275,10 @@ func getProjectData(ctx *dep.Ctx, pkgT gps.PackageTree, cpr string, sm *gps.Sour
 				}

 				continue
+			} else {


continue means no need for an else branch

sdboyer · 2017-01-30T03:05:00Z

cmd/dep/init.go

@@ -237,6 +238,15 @@ func getProjectData(ctx *dep.Ctx, pkgT gps.PackageTree, cpr string, sm *gps.Sour
 	packages := make(map[string]bool)
 	notondisk := make(map[gps.ProjectRoot]bool)
 	ondisk := make(map[gps.ProjectRoot]gps.Version)
+
+	printNewDeP := func(pr gps.ProjectRoot, sm *gps.SourceMgr) {
+		message := "Cloning"


Might be better as "Cloned", past tense, because this will only print after the sm is done pulling the dep down.

Actually, might be better to switch out the word entirely - "cloning" applies to git, but git isn't all we're dealing with here. Maybe "Fetched latest of"? I think that's generic enough. It also glosses over whether, in git terms, it's actually doing a clone, or just ensuring our local clone is already up to date.

sdboyer · 2017-01-30T03:27:09Z

Ok doing so has increased speed drastically. Though the way Ive written it not sure it needs to be a closure.

My reasoning behind making it a closure was reuse - there are a couple more places from which it needs to be called. Right now, only the part of the code dealing with direct dependencies is instrumented. Look down in the dft closure - that's the depth-first explorer which transitively visits all dependencies. Everything discovered through there needs to be treated, as well.

Im still analyzing the code to make sure the new goroutine to call the closure always has a chance to complete.

They're all guaranteed to complete and print, but not by anything directly visible in the code here. All of those SyncSourceFor() calls are blocked on actions that are necessarily also called elsewhere (either in Solve(), or in a blocking manner by the txn writer); they'll complete and print as soon as the other calls do.

This approach doesn't guarantee we'll see everything printed - for example, transitive deps of deps that aren't in GOPATH won't ever get visited, so a printing goroutine will never be run for them. But I'm not even sure that's really solvable, so this is still a substantial improvement over what we have today.

EDIT: note that i'm not saying it's a good practice to just rely on the underlying implementation for completion - just that it will happen. We could certainly add a mechanism to ensure these goroutines complete in the code here - just so long as it doesn't cause us to lose concurrency.

sdboyer · 2017-01-30T03:27:32Z

cmd/dep/init.go

@@ -237,6 +238,15 @@ func getProjectData(ctx *dep.Ctx, pkgT gps.PackageTree, cpr string, sm *gps.Sour
 	packages := make(map[string]bool)
 	notondisk := make(map[gps.ProjectRoot]bool)
 	ondisk := make(map[gps.ProjectRoot]gps.Version)
+
+	printNewDeP := func(pr gps.ProjectRoot, sm *gps.SourceMgr) {


nit: s/DeP/Dep/

mattn · 2017-01-30T04:21:08Z

cmd/dep/init.go

@@ -266,6 +276,8 @@ func getProjectData(ctx *dep.Ctx, pkgT gps.PackageTree, cpr string, sm *gps.Sour

 				continue
 			}
+			go printNewDep(pr, sm)


Why no waiting finish of this goroutine?

see #194 (comment)

mattn · 2017-01-30T04:21:21Z

cmd/dep/init.go

@@ -363,6 +375,7 @@ func getProjectData(ctx *dep.Ctx, pkgT gps.PackageTree, cpr string, sm *gps.Sour
 				}
 			} else {
 				dependencies[pr] = []string{pkg}
+				go printNewDep(pr, sm)


xmattstrongx · 2017-01-30T18:34:15Z

@sdboyer Is there anything else needed here for this issue to close?

sdboyer · 2017-01-30T18:58:42Z

@xmattstrongx i think some feedback from @peterbourgon would be useful, as it was his note that motivated putting this up in the first place. i'm adding him as a reviewer.

peterbourgon

I like that it prints something for each dep. I'm confused by the "Fetched latest of dep" verbiage, both of those words signal something specific to me, and it's not what's actually going on. Init is just cloning each identified dep to GOPATH/pkg/dep/sources, right? What about just "Fetched dep" or "Cached dep"?

Also, I don't understand why each printNewDep call is invoked in a new goroutine rather than called synchronously, and the explanation you linked to @mattn doesn't help me understand. Can you explain?

xmattstrongx · 2017-01-31T04:05:27Z

@peterbourgon We decided to make each call happen in a new goroutine because the underlying call to gps.SourceMgr.SyncSourceFor was eating up about 1.5-1.8 seconds per dep.

As far as the output verbage @sdboyer and I went back and forth a couple times on what it should display. I do like the Cached dep

sdboyer · 2017-01-31T04:07:00Z

ditto what @xmattstrongx said re: separate goroutines.

What about just "Fetched dep" or "Cached dep"?

Ooh yeah, I liked "Cached dep" even more. I was trying to come up with something to avoid saying "cloned," as that's git/hg-specific, and also isn't the action it's performing if the dep is already present in the cache. So, definitely, this is better.

peterbourgon · 2017-01-31T04:07:55Z

@xmattstrongx Thanks for the explanation. Is SyncSourceFor the bit that's actually doing the work of init?

xmattstrongx · 2017-01-31T04:17:44Z

per a previous slack conversation with @sdboyer

this'll (SyncSourceFor) all be reused by the solver or exporter when it comes time to do their job, so there's no duplication of work happening

peterbourgon · 2017-01-31T04:18:06Z

I'm sorry, that doesn't seem to answer my question. Is SyncSourceFor the bit that's actually caching the relevant dep?

sdboyer · 2017-01-31T04:21:38Z

@peterbourgon I guess that depends on what "the work of init" means? I'm not sure what you're asking by that.

SyncSourceFor just brings the local cached instance of a source up to date (or clones/checks it out initially). We're choosing to target it as the operation to report because it's intuitive and also the one that tends to be expensive, and so is the most likely to give user incremental and comprehensible feedback.

The same SyncSourceFor (or calls that have an equivalent result) are performed implicitly by both solving and exporting the dep tree to vendor. We're just promoting that action to happen out here, so that we can effectively signal when it's complete. We have to pull it out to here because, when it happens implicitly, there's no signaling mechanism to let us know when the op is complete.

peterbourgon · 2017-01-31T04:24:03Z

OK. Calling the closure printNewDep belies its importance; it's doing more than just printing! I suggest syncNewDep or syncDep or something like this.

xmattstrongx · 2017-01-31T04:25:39Z

Was violating single responsibility. The new name makes sense to me. Gonna make the change to the function name to syncDep and output to read

Cached dep

sdboyer · 2017-01-31T19:09:27Z

OK, I think we're good to merge this now. Thanks!

The current rules for github usernames only allow for alphanumeric characters or single hyphens and they cannot begin or end with a hyphen. In the past however github username rules were less strict and we need to support these (issue golang#194). Using the Google BigQuery public github dataset, I've checked the usernames of all public commits against the currently defined regex in deduce.go. From these results I've concluded that usernames with multiple consecutive hyphens and usernames that end with a hyphen were allowed in the past and do exist. Fortunately these are the only exceptions I've found, there were no usernames that started with a hyphen or contained any other special characters. In addition, this change now also allows one-letter usernames.

googlebot added the cla: no label Jan 29, 2017

sdboyer self-requested a review January 29, 2017 19:15

googlebot added cla: yes and removed cla: no labels Jan 29, 2017

sdboyer reviewed Jan 29, 2017

View reviewed changes

sdboyer reviewed Jan 30, 2017

View reviewed changes

xmattstrongx force-pushed the master branch from 7eac911 to f383865 Compare January 30, 2017 04:13

mattn suggested changes Jan 30, 2017

View reviewed changes

sdboyer requested a review from peterbourgon January 30, 2017 18:58

peterbourgon reviewed Jan 31, 2017

View reviewed changes

Logging out a message to the user whenever a new dependency is found.

fbf21bd

xmattstrongx force-pushed the master branch from 5456c4e to fbf21bd Compare January 31, 2017 04:27

sdboyer merged commit cd7b109 into golang:master Jan 31, 2017

sdboyer mentioned this pull request Jan 31, 2017

Feedback: init and status should provide some user feedback #62

Closed

sdboyer mentioned this pull request Feb 18, 2017

Panic (maybe a race?) when init on kops #250

Closed

sdboyer mentioned this pull request Sep 6, 2017

Dep init takes forever #1129

Closed

xmattstrongx mentioned this pull request Sep 17, 2017

Adding UX output to dep init #1176

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding new dependency logging #194

Adding new dependency logging #194

xmattstrongx commented Jan 29, 2017 •

edited

Loading

googlebot commented Jan 29, 2017

xmattstrongx commented Jan 29, 2017

googlebot commented Jan 29, 2017

sdboyer Jan 29, 2017

xmattstrongx Jan 29, 2017

sdboyer Jan 29, 2017

sdboyer Jan 30, 2017

sdboyer Jan 30, 2017

sdboyer Jan 30, 2017 •

edited

Loading

sdboyer commented Jan 30, 2017 •

edited

Loading

sdboyer Jan 30, 2017

xmattstrongx Jan 30, 2017

mattn Jan 30, 2017

sdboyer Jan 30, 2017

mattn Jan 30, 2017

xmattstrongx commented Jan 30, 2017

sdboyer commented Jan 30, 2017

peterbourgon left a comment

xmattstrongx commented Jan 31, 2017 •

edited

Loading

sdboyer commented Jan 31, 2017

peterbourgon commented Jan 31, 2017

xmattstrongx commented Jan 31, 2017

peterbourgon commented Jan 31, 2017 •

edited

Loading

sdboyer commented Jan 31, 2017 •

edited

Loading

peterbourgon commented Jan 31, 2017 •

edited

Loading

xmattstrongx commented Jan 31, 2017 •

edited

Loading

sdboyer commented Jan 31, 2017

Adding new dependency logging #194

Adding new dependency logging #194

Conversation

xmattstrongx commented Jan 29, 2017 • edited Loading

googlebot commented Jan 29, 2017

xmattstrongx commented Jan 29, 2017

googlebot commented Jan 29, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sdboyer Jan 30, 2017 • edited Loading

Choose a reason for hiding this comment

sdboyer commented Jan 30, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

xmattstrongx commented Jan 30, 2017

sdboyer commented Jan 30, 2017

peterbourgon left a comment

Choose a reason for hiding this comment

xmattstrongx commented Jan 31, 2017 • edited Loading

sdboyer commented Jan 31, 2017

peterbourgon commented Jan 31, 2017

xmattstrongx commented Jan 31, 2017

peterbourgon commented Jan 31, 2017 • edited Loading

sdboyer commented Jan 31, 2017 • edited Loading

peterbourgon commented Jan 31, 2017 • edited Loading

xmattstrongx commented Jan 31, 2017 • edited Loading

sdboyer commented Jan 31, 2017

xmattstrongx commented Jan 29, 2017 •

edited

Loading

sdboyer Jan 30, 2017 •

edited

Loading

sdboyer commented Jan 30, 2017 •

edited

Loading

xmattstrongx commented Jan 31, 2017 •

edited

Loading

peterbourgon commented Jan 31, 2017 •

edited

Loading

sdboyer commented Jan 31, 2017 •

edited

Loading

peterbourgon commented Jan 31, 2017 •

edited

Loading

xmattstrongx commented Jan 31, 2017 •

edited

Loading