cmd/snap: support for --ensure argument for snap debug timings #6793

stolowski · 2019-04-29T15:08:36Z

Support for displaying timings related to the given "ensure"-activity, e.g.
snap debug timings --ensure=seed. Possible values for "ensure" currently are: "seed", "become-operational", "auto-refresh", "refresh-catalogs", "refresh-hints".

pedronis

thank you, some initial comments

pedronis · 2019-05-03T11:52:53Z

cmd/snap/cmd_debug_timings.go


 	// now combine with the other data about the change
 	chg, err := x.client.Change(chgid)
 	if err != nil {
 		return err
 	}
+
+	if len(timings.EnsureTimings) > 0 {


I wonder if we want a single tabwriter and somehow make the two parts align more, or even use a single header and match concepts somehow?

Yes, that's a nice idea, done. Here is sample result:

pawel@ubuntu:~/gocode/src/github.com/snapcore/snapd/cmd/snap$ ./snap debug timings --ensure=auto-refresh --verbose ID Status Doing Undoing Label Summary ensure - 668ms - auto-refresh query store and setup auto-refresh change 206 Done 13ms - prerequisites Ensure prerequisites for "gnome-3-28-1804" are available 207 Done 1899ms - download-snap Download snap "gnome-3-28-1804" (40) from channel "stable" ^ 1893ms - download download snap "gnome-3-28-1804" 208 Done 664ms - validate-snap Fetch and check assertions for snap "gnome-3-28-1804" (40) 209 Done 949ms - mount-snap Mount snap "gnome-3-28-1804" (40) ^ 568ms - check-snap check snap "gnome-3-28-1804" ^ 348ms - setup-snap setup snap "gnome-3-28-1804" 210 Done 8ms - run-hook Run pre-refresh hook of "gnome-3-28-1804" snap if present

pedronis · 2019-05-03T11:53:43Z

cmd/snap/cmd_debug_timings.go

@@ -32,7 +32,8 @@ import (

 type cmdChangeTimings struct {
 	changeIDMixin
-	Verbose bool `long:"verbose"`
+	EnsureID string `long:"ensure"`


s/ID/Tag/ perhaps? also in the rest?

pedronis · 2019-05-03T11:54:28Z

cmd/snap/cmd_debug_timings.go

 	}

-	if err := x.client.DebugGet("change-timings", &timings, map[string]string{"change-id": chgid}); err != nil {
+	if err := x.client.DebugGet("change-timings", &timings, map[string]string{"change-id": chgid, "ensure-id": x.EnsureID}); err != nil {


s/ensure-id/ensure/ ?

pedronis · 2019-05-03T11:56:43Z

daemon/api_debug.go

+			}
+			return BadRequest("multiple timings found for ensure %q, please specify change ID (%s)", ensureID, strings.Join(changes, ","))
+		}
+		ensureChangeID := ensures[0].Tags["change-id"]


I would think we want the latest one, no? not the first

EDIT: AH, we fail if we have more than one, as I said probably we just want to return the latest instead. And have a --all version that shows all the known ensures.

Good idea, done.

pedronis · 2019-05-03T11:57:55Z

daemon/api_debug.go

+		if len(ensures) > 1 {
+			var changes []string
+			for _, ensure := range ensures {
+				if chg, ok := ensure.Tags[""]; ok {


I don't understand this line, what is Tag "" ? is this code tested? was it meant to be "change-id" ?

Indeed, a bad edit, and I haven't tested this error path. Debug timings client currently has no tests at all, so I only test this manually. Will add some tests soon. Thanks for catching!

pedronis · 2019-05-03T12:01:59Z

daemon/api_debug.go

@@ -152,7 +194,8 @@ func getDebug(c *Command, r *http.Request, user *auth.UserState) Response {
 		}, nil)
 	case "change-timings":
 		chgID := query.Get("change-id")
-		return getChangeTimings(st, chgID)
+		ensureID := query.Get("ensure-id")


pedronis · 2019-05-03T12:03:29Z

cmd/snap/cmd_debug_timings.go

@@ -42,6 +43,7 @@ func init() {
 		func() flags.Commander {
 			return &cmdChangeTimings{}
 		}, changeIDMixinOptDesc.also(map[string]string{
+			"ensure": i18n.G("Show timings for a change related to the given Ensure"),


what we are looking for are really subpart of Ensure and changes triggered from those, so maybe s/Ensure/Ensure activity/ ?

…ault.

… activities of given ensure, and use single tab writer.

bboozzoo

Some nitpicks & suggestions. The PR seems to be missing tests?

cmd/snap/cmd_debug_timings.go

bboozzoo · 2019-05-07T08:06:27Z

cmd/snap/cmd_debug_timings.go

+
+	// If a specific change was requested, we expect exactly one timingsData element.
+	// If "ensure" activity was requested, we may get multiple elements (for multiple executions of the ensure)
+	for _, td := range timings {


Nitpick: naybe it'd be worthwhile to split this into 2 separate helpers:

func printChangeTimings(out io.Writer, timings *timingsData, verbose bool) { ... } func printEnsureTimings(out io.Writer, timings []timingsData, verbose bool) { ... for _, td := range timings { if td.ChangeID != "" { printChangeTimings(out, &td, verbose) } } } func (x *cmdChangeTimings) Execute(args []string) error { ... if chgid != "" && len(timings) > 0 { printChangeTimings(w, &timings[0], x.Verbose) } else { printChangeTimings(w, timings, x.Verbose) } ... w.Flush() }

bboozzoo · 2019-05-07T08:11:15Z

daemon/api_debug.go

+	// If ensure tag was passed by the client, find its related changes;
+	// we can have many ensure executions and their changes in the responseData array.
+	if ensureTag != "" {
+		ensures, err := timings.Get(st, -1, func(tags map[string]string) bool {


Nitpick: this could be captured in func collectEnsureTimings(st *state.State, ensureTag string) ([]*debugTimings, error) helper

codecov-io · 2019-05-07T10:40:43Z

Codecov Report

Merging #6793 into master will decrease coverage by 0.02%.
The diff coverage is 65.19%.

@@            Coverage Diff             @@
##           master    #6793      +/-   ##
==========================================
- Coverage    79.5%   79.48%   -0.03%     
==========================================
  Files         608      609       +1     
  Lines       46910    46991      +81     
==========================================
+ Hits        37298    37353      +55     
- Misses       6634     6653      +19     
- Partials     2978     2985       +7

Impacted Files	Coverage Δ
overlord/snapstate/snapstate.go	`82.29% <ø> (ø)`	⬆️
cmd/snap/cmd_debug_timings.go	`7.77% <0%> (-3.16%)`	⬇️
overlord/devicestate/handlers.go	`72.84% <100%> (ø)`	⬆️
overlord/devicestate/helpers.go	`100% <100%> (ø)`	⬆️
overlord/ifacestate/helpers.go	`75.46% <100%> (+0.28%)`	⬆️
daemon/api_model.go	`72.41% <100%> (ø)`	⬆️
overlord/devicestate/firstboot.go	`80.64% <100%> (ø)`	⬆️
overlord/devicestate/devicectx.go	`69.23% <100%> (ø)`	⬆️
overlord/devicestate/devicestate.go	`80% <100%> (+0.63%)`	⬆️
gadget/gadget.go	`95.52% <100%> (+0.02%)`	⬆️
... and 16 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 7e37021...043ade4. Read the comment docs.

stolowski · 2019-05-07T11:25:40Z

Looks like I broke --last, investigating

…s when quering for ensure timings.

bboozzoo

LGTM. Left one open question.

bboozzoo · 2019-05-08T06:49:01Z

daemon/api_debug.go

+}
+
+func collectEnsureTimings(st *state.State, ensureTag string, allEnsures bool) ([]*debugTimings, error) {
+	ensures, err := timings.Get(st, -1, func(tags map[string]string) bool {


I looked at timings.Get, wondering about the case when allEnsures == false, when we grab/unmarshal/filter all the entries, but only push the last one out. Given that there will always be quite a bit of timings data, must of the work is being discarded. OTOH, maybe it's not a problem after all.

I don't think performance it's a concern as this is a debug interface, also I'm not sure this can be avoided given that we need to look into tags. FWTW we currently keep up to 100 "root-level" timings (but yes, they can have a few nested timings each).

pedronis · 2019-05-08T07:09:51Z

cmd/snap/cmd_debug_timings.go

+		if len(td.EnsureTimings) > 0 {
+			for _, t := range td.EnsureTimings {
+				if x.Verbose {
+					fmt.Fprintf(w, "%s\t%s\t%11s\t%11s\t%s\t%s\n", "ensure", "-", formatDuration(t.Duration), "-", t.Label, t.Summary)


I am a bit confused, what do we do with level/nesting here, the timings from Ensure itself can be nested, no?

As discussed, I forgot about nesting indicator here, thanks for catching.

It's now added, plus some refactoring to have one printing helper for all timings. Note though, we won't see any nesting for current ensure timings (unless I missed something) as are all level 0; for the "refresh-catalogs" ensure discussed on IRC, we have "refresh-catalogs" root timing node (with tags), and two level-0 measurements under it. So the output is:

pawel@ubuntu:~/gocode/src/github.com/snapcore/snapd/cmd/snap$ ./snap debug timings --ensure=refresh-catalogs --all --verbose ID Status Doing Undoing Label Summary ensure 34ms - get-sections query store for sections ensure 1835ms - write-catalogs query store for catalogs ensure 209ms - get-sections query store for sections ensure 374ms - write-catalogs query store for catalogs

This is different for task timings, because we nest them visually even for level 0 as they are displayed under task info line coming from Task. Maybe we should add artifical line for ensure timings (with just the requested ensure tag name) and nest everything with level 0 under it?

yes, as we discussed the latter seems maybe a good idea (for clarity mostly), but as we also discussed can be a follow up

…use one print helper for all timings.

pedronis · 2019-05-08T11:25:11Z

@stolowski This is looking good from my POV but don't have time to do another deep review. It has changed also quite a bit, it just needs any 2 reviews now assuming no more output changes for this round.

changed quite a bit since

mvo5

Looks good! I would love to have a small unit test for cmd_debug_timings.go - but given that we did not have one before this should not block things I think.

stolowski · 2019-05-10T09:07:00Z

Unit tests for all snap debug timings functionality added in #6858

bboozzoo

LGTM

bboozzoo · 2019-05-10T13:00:32Z

cmd/snap/cmd_debug_timings.go

@@ -42,6 +44,8 @@ func init() {
 		func() flags.Commander {
 			return &cmdChangeTimings{}
 		}, changeIDMixinOptDesc.also(map[string]string{
+			"ensure": i18n.G("Show timings for a change related to the given Ensure activity (one of: auto-refresh, become-operational, refresh-catalogs, refresh-hints, seed)"),


It's a debug command, so not a high priority, but I wonder whether we could take some steps to make sure the list gets updated when new ensure tags are added.

stolowski added 7 commits April 10, 2019 14:37

Merge branch 'timings-client' into timings-client-ensure

6d53d4c

Merge branch 'more-measurements' into timings-client-ensure

0c870b9

Merge branch 'snap-debug-use-get' into timings-client-ensure

15558c7

Handle --ensure.

5a3e4d5

Fix client struct definition.

8a2355d

Merge branch 'master' into timings-client-ensure

e5c1197

Fix the comment.

b423522

pedronis self-requested a review May 1, 2019 10:22

pedronis reviewed May 3, 2019

View reviewed changes

stolowski added 5 commits May 6, 2019 09:49

Merge branch 'master' into timings-client-ensure

dfc6084

Rename ensure-id to ensure and EnsureID to EnsureTag.

253951c

Suppoer multiple ensure executions with --all and the last one by def…

6682976

…ault.

Refactored debug timings client and api to support reporting multiple…

e10a2cb

… activities of given ensure, and use single tab writer.

Fix format.

2f40753

bboozzoo reviewed May 7, 2019

View reviewed changes

stolowski added 3 commits May 7, 2019 10:30

Added unit tests.

ee3a768

Change is optional for ensure timings.

f359039

Moved change/ensure related code of debug timings into helpers.

043ade4

Merge branch 'master' into timings-client-ensure

5c0678a

Fix --last handling broken by previous changes. Ignore missing change…

243b4cf

…s when quering for ensure timings.

pedronis self-requested a review May 7, 2019 15:38

bboozzoo previously approved these changes May 8, 2019

View reviewed changes

pedronis reviewed May 8, 2019

View reviewed changes

stolowski added 2 commits May 8, 2019 10:35

Handle nesting for ensure timing output. Refactored printing code to …

2eddbe9

…use one print helper for all timings.

List all possible ensure tags in snap debug timings --help.

b5a0155

mvo5 approved these changes May 9, 2019

View reviewed changes

stolowski mentioned this pull request May 10, 2019

cmd/snap: unit tests for debug timings #6858

Merged

bboozzoo approved these changes May 10, 2019

View reviewed changes

bboozzoo merged commit c9c7c97 into snapcore:master May 10, 2019

stolowski mentioned this pull request May 23, 2019

cmd/snap: tweak the output of snap debug timings --ensure=... #6896

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/snap: support for --ensure argument for snap debug timings #6793

cmd/snap: support for --ensure argument for snap debug timings #6793

stolowski commented Apr 29, 2019 •

edited by pedronis

pedronis left a comment

pedronis May 3, 2019

stolowski May 6, 2019

pedronis May 3, 2019

pedronis May 3, 2019

pedronis May 3, 2019

stolowski May 6, 2019

pedronis May 3, 2019

stolowski May 6, 2019

pedronis May 3, 2019

pedronis May 3, 2019

bboozzoo left a comment

bboozzoo May 7, 2019

bboozzoo May 7, 2019

codecov-io commented May 7, 2019

stolowski commented May 7, 2019

bboozzoo left a comment

bboozzoo May 8, 2019

stolowski May 9, 2019

pedronis May 8, 2019

stolowski May 8, 2019 •

edited

pedronis May 8, 2019

pedronis commented May 8, 2019

mvo5 left a comment

stolowski commented May 10, 2019

bboozzoo left a comment

bboozzoo May 10, 2019

cmd/snap: support for --ensure argument for snap debug timings #6793

cmd/snap: support for --ensure argument for snap debug timings #6793

Conversation

stolowski commented Apr 29, 2019 • edited by pedronis

pedronis left a 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

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bboozzoo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-io commented May 7, 2019

Codecov Report

stolowski commented May 7, 2019

bboozzoo left a 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

stolowski May 8, 2019 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pedronis commented May 8, 2019

mvo5 left a comment

Choose a reason for hiding this comment

stolowski commented May 10, 2019

bboozzoo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

stolowski commented Apr 29, 2019 •

edited by pedronis

stolowski May 8, 2019 •

edited