Merge pull request canonical#6793 from stolowski/timings-client-ensure

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

cmd/snap/cmd_debug_timings.go

@@ -32,7 +32,9 @@ import (
 
 type cmdChangeTimings struct {
 	changeIDMixin
-	Verbose bool `long:"verbose"`
+	EnsureTag string `long:"ensure"`
+	All       bool   `long:"all"`
+	Verbose   bool   `long:"verbose"`
 }
 
 func init() {
@@ -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)"),
+			"all":    i18n.G("Show timings for all executions of the given Ensure activity, not just the latest"),
 			// TRANSLATORS: This should not start with a lowercase letter.
 			"verbose": i18n.G("Show more information"),
 		}), changeIDMixinArgDesc)
@@ -58,7 +62,21 @@ func formatDuration(dur time.Duration) string {
 	return fmt.Sprintf("%dms", dur/time.Millisecond)
 }
 
-func printTiming(w io.Writer, t *Timing, verbose, doing bool) {
+func printTiming(w io.Writer, verbose bool, nestLevel int, id, status, doingTimeStr, undoingTimeStr, label, summary string) {
+	// don't display id for nesting>1, instead show nesting indicator
+	if nestLevel > 0 {
+		id = strings.Repeat(" ", nestLevel) + "^"
+	}
+	// Duration formats to 17m14.342s or 2.038s or 970ms, so with
+	// 11 chars we can go up to 59m59.999s
+	if verbose {
+		fmt.Fprintf(w, "%s\t%s\t%11s\t%11s\t%s\t%s\n", id, status, doingTimeStr, undoingTimeStr, label, strings.Repeat(" ", 2*nestLevel)+summary)
+	} else {
+		fmt.Fprintf(w, "%s\t%s\t%11s\t%11s\t%s\n", id, status, doingTimeStr, undoingTimeStr, strings.Repeat(" ", 2*nestLevel)+summary)
+	}
+}
+
+func printTaskTiming(w io.Writer, t *Timing, verbose, doing bool) {
 	var doingTimeStr, undoingTimeStr string
 	if doing {
 		doingTimeStr = formatDuration(t.Duration)
@@ -69,72 +87,114 @@ func printTiming(w io.Writer, t *Timing, verbose, doing bool) {
 			undoingTimeStr = formatDuration(t.Duration)
 		}
 	}
-	if verbose {
-		fmt.Fprintf(w, "%s\t \t%11s\t%11s\t%s\t%s\n", strings.Repeat(" ", t.Level+1)+"^", doingTimeStr, undoingTimeStr, t.Label, strings.Repeat(" ", 2*(t.Level+1))+t.Summary)
-	} else {
-		fmt.Fprintf(w, "%s\t \t%11s\t%11s\t%s\n", strings.Repeat(" ", t.Level+1)+"^", doingTimeStr, undoingTimeStr, strings.Repeat(" ", 2*(t.Level+1))+t.Summary)
-	}
+	printTiming(w, verbose, t.Level+1, "", "", doingTimeStr, undoingTimeStr, t.Label, t.Summary)
 }
 
-func (x *cmdChangeTimings) Execute(args []string) error {
-	if len(args) > 0 {
-		return ErrExtraArgs
-	}
-	chgid, err := x.GetChangeID()
+func (x *cmdChangeTimings) printChangeTimings(w io.Writer, timing *timingsData) error {
+	chgid := timing.ChangeID
+	chg, err := x.client.Change(chgid)
 	if err != nil {
 		return err
 	}
 
-	// gather debug timings first
-	var timings map[string]struct {
+	for _, t := range chg.Tasks {
+		doingTime := formatDuration(timing.ChangeTimings[t.ID].DoingTime)
+		if timing.ChangeTimings[t.ID].DoingTime == 0 {
+			doingTime = "-"
+		}
+		undoingTime := formatDuration(timing.ChangeTimings[t.ID].UndoingTime)
+		if timing.ChangeTimings[t.ID].UndoingTime == 0 {
+			undoingTime = "-"
+		}
+
+		printTiming(w, x.Verbose, 0, t.ID, t.Status, doingTime, undoingTime, t.Kind, t.Summary)
+		for _, nested := range timing.ChangeTimings[t.ID].DoingTimings {
+			showDoing := true
+			printTaskTiming(w, &nested, x.Verbose, showDoing)
+		}
+		for _, nested := range timing.ChangeTimings[t.ID].UndoingTimings {
+			showDoing := false
+			printTaskTiming(w, &nested, x.Verbose, showDoing)
+		}
+	}
+
+	return nil
+}
+
+func (x *cmdChangeTimings) printEnsureTimings(w io.Writer, timings []*timingsData) error {
+	for _, td := range timings {
+		for _, t := range td.EnsureTimings {
+			printTiming(w, x.Verbose, t.Level, "ensure", "", formatDuration(t.Duration), "-", t.Label, t.Summary)
+		}
+
+		// change is optional for ensure timings
+		if td.ChangeID != "" {
+			x.printChangeTimings(w, td)
+		}
+	}
+	return nil
+}
+
+type timingsData struct {
+	ChangeID      string   `json:"change-id"`
+	EnsureTimings []Timing `json:"ensure-timings,omitempty"`
+	ChangeTimings map[string]struct {
 		DoingTime      time.Duration `json:"doing-time,omitempty"`
 		UndoingTime    time.Duration `json:"undoing-time,omitempty"`
 		DoingTimings   []Timing      `json:"doing-timings,omitempty"`
 		UndoingTimings []Timing      `json:"undoing-timings,omitempty"`
+	} `json:"change-timings,omitempty"`
+}
+
+func (x *cmdChangeTimings) Execute(args []string) error {
+	if len(args) > 0 {
+		return ErrExtraArgs
 	}
 
-	if err := x.client.DebugGet("change-timings", &timings, map[string]string{"change-id": chgid}); err != nil {
-		return err
+	if x.EnsureTag != "" && x.Positional.ID != "" {
+		return fmt.Errorf("cannot use 'ensure' and change id together")
+	}
+	if x.All && (x.Positional.ID != "" || x.LastChangeType != "") {
+		return fmt.Errorf("cannot use 'all' with change id or 'last'")
 	}
 
-	// now combine with the other data about the change
-	chg, err := x.client.Change(chgid)
-	if err != nil {
+	var chgid string
+	var err error
+	if x.EnsureTag == "" {
+		// GetChangeID takes care of --last=... if change ID was not specified by the user
+		chgid, err = x.GetChangeID()
+		if err != nil {
+			return err
+		}
+	}
+
+	// gather debug timings first
+	var timings []*timingsData
+	var allEnsures string
+	if x.All {
+		allEnsures = "true"
+	} else {
+		allEnsures = "false"
+	}
+	if err := x.client.DebugGet("change-timings", &timings, map[string]string{"change-id": chgid, "ensure": x.EnsureTag, "all": allEnsures}); err != nil {
 		return err
 	}
+
 	w := tabWriter()
 	if x.Verbose {
 		fmt.Fprintf(w, "ID\tStatus\t%11s\t%11s\tLabel\tSummary\n", "Doing", "Undoing")
 	} else {
 		fmt.Fprintf(w, "ID\tStatus\t%11s\t%11s\tSummary\n", "Doing", "Undoing")
 	}
-	for _, t := range chg.Tasks {
-		doingTime := formatDuration(timings[t.ID].DoingTime)
-		if timings[t.ID].DoingTime == 0 {
-			doingTime = "-"
-		}
-		undoingTime := formatDuration(timings[t.ID].UndoingTime)
-		if timings[t.ID].UndoingTime == 0 {
-			undoingTime = "-"
-		}
-		summary := t.Summary
-		// Duration formats to 17m14.342s or 2.038s or 970ms, so with
-		// 11 chars we can go up to 59m59.999s
-		if x.Verbose {
-			fmt.Fprintf(w, "%s\t%s\t%11s\t%11s\t%s\t%s\n", t.ID, t.Status, doingTime, undoingTime, t.Kind, summary)
-		} else {
-			fmt.Fprintf(w, "%s\t%s\t%11s\t%11s\t%s\n", t.ID, t.Status, doingTime, undoingTime, summary)
-		}
 
-		for _, nested := range timings[t.ID].DoingTimings {
-			showDoing := true
-			printTiming(w, &nested, x.Verbose, showDoing)
-		}
-		for _, nested := range timings[t.ID].UndoingTimings {
-			showDoing := false
-			printTiming(w, &nested, x.Verbose, showDoing)
-		}
+	// 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)
+	if chgid != "" && len(timings) > 0 {
+		x.printChangeTimings(w, timings[0])
+	} else {
+		x.printEnsureTimings(w, timings)
 	}
+
 	w.Flush()
 	fmt.Fprintln(Stdout)
 

daemon/api_debug.go

@@ -21,6 +21,7 @@ package daemon
 
 import (
 	"encoding/json"
+	"fmt"
 	"net/http"
 	"sort"
 	"time"
@@ -91,20 +92,26 @@ type changeTimings struct {
 	UndoingTimings []*timings.TimingJSON `json:"undoing-timings,omitempty"`
 }
 
-func getChangeTimings(st *state.State, changeID string) Response {
+type debugTimings struct {
+	ChangeID      string                    `json:"change-id"`
+	EnsureTimings []*timings.TimingJSON     `json:"ensure-timings,omitempty"`
+	ChangeTimings map[string]*changeTimings `json:"change-timings,omitempty"`
+}
+
+func collectChangeTimings(st *state.State, changeID string) (map[string]*changeTimings, error) {
 	chg := st.Change(changeID)
 	if chg == nil {
-		return BadRequest("cannot find change: %v", changeID)
+		return nil, fmt.Errorf("cannot find change: %v", changeID)
 	}
 
-	doingTimingsByTask := make(map[string][]*timings.TimingJSON)
-	undoingTimingsByTask := make(map[string][]*timings.TimingJSON)
-
 	// collect "timings" for tasks of given change
 	stateTimings, err := timings.Get(st, -1, func(tags map[string]string) bool { return tags["change-id"] == changeID })
 	if err != nil {
-		return InternalError("cannot get timings of change %s: %v", changeID, err)
+		return nil, fmt.Errorf("cannot get timings of change %s: %v", changeID, err)
 	}
+
+	doingTimingsByTask := make(map[string][]*timings.TimingJSON)
+	undoingTimingsByTask := make(map[string][]*timings.TimingJSON)
 	for _, tm := range stateTimings {
 		taskID := tm.Tags["task-id"]
 		if status, ok := tm.Tags["task-status"]; ok {
@@ -114,7 +121,7 @@ func getChangeTimings(st *state.State, changeID string) Response {
 			case status == state.UndoingStatus.String():
 				undoingTimingsByTask[taskID] = tm.NestedTimings
 			default:
-				return InternalError("unexpected task status %q for timing of task %s", status, taskID)
+				return nil, fmt.Errorf("unexpected task status %q for timing of task %s", status, taskID)
 			}
 		}
 	}
@@ -128,7 +135,69 @@ func getChangeTimings(st *state.State, changeID string) Response {
 			UndoingTimings: undoingTimingsByTask[t.ID()],
 		}
 	}
-	return SyncResponse(m, nil)
+	return m, nil
+}
+
+func collectEnsureTimings(st *state.State, ensureTag string, allEnsures bool) ([]*debugTimings, error) {
+	ensures, err := timings.Get(st, -1, func(tags map[string]string) bool {
+		return tags["ensure"] == ensureTag
+	})
+	if err != nil {
+		return nil, fmt.Errorf("cannot get timings of ensure %s: %v", ensureTag, err)
+	}
+	if len(ensures) == 0 {
+		return nil, fmt.Errorf("cannot find ensure: %v", ensureTag)
+	}
+
+	// If allEnsures is true, then report all activities of given ensure, otherwise just the latest
+	first := len(ensures) - 1
+	if allEnsures {
+		first = 0
+	}
+	var responseData []*debugTimings
+	var changeTimings map[string]*changeTimings
+	for _, ensureTm := range ensures[first:] {
+		ensureChangeID := ensureTm.Tags["change-id"]
+		// change is optional for ensure timings
+		if ensureChangeID != "" {
+			// ignore an error when getting a change, it may no longer be present in the state
+			changeTimings, _ = collectChangeTimings(st, ensureChangeID)
+		}
+		debugTm := &debugTimings{
+			ChangeID:      ensureChangeID,
+			ChangeTimings: changeTimings,
+			EnsureTimings: ensureTm.NestedTimings,
+		}
+		responseData = append(responseData, debugTm)
+	}
+
+	return responseData, nil
+}
+
+func getChangeTimings(st *state.State, changeID, ensureTag string, allEnsures bool) Response {
+	// 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 != "" {
+		responseData, err := collectEnsureTimings(st, ensureTag, allEnsures)
+		if err != nil {
+			return BadRequest(err.Error())
+		}
+		return SyncResponse(responseData, nil)
+	}
+
+	// timings for single change ID
+	changeTimings, err := collectChangeTimings(st, changeID)
+	if err != nil {
+		return BadRequest(err.Error())
+	}
+
+	responseData := []*debugTimings{
+		{
+			ChangeID:      changeID,
+			ChangeTimings: changeTimings,
+		},
+	}
+	return SyncResponse(responseData, nil)
 }
 
 func getDebug(c *Command, r *http.Request, user *auth.UserState) Response {
@@ -152,7 +221,9 @@ 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")
+		all := query.Get("all")
+		return getChangeTimings(st, chgID, ensureID, all == "true")
 	default:
 		return BadRequest("unknown debug aspect %q", aspect)
 	}