feat(scanner): compute and render per-scanner duration_ms (#667)

The scan report carried per-scanner started_at/completed_at but no
duration, and the CLI rendered no per-scanner timing. Add a derived
duration_ms to each scanner status and surface it in the CLI:

- ScannerJobStatus gains a duration_ms field and a Duration() helper;
  the engine recomputes it once both timestamps are known (the live
  scan path sets start and completion in separate updates).
- security status grows a DURATION column.
- security report renders a per-scanner "Scanner timing" block.
- CLI reads duration_ms, falling back to started_at/completed_at for
  reports produced before the field existed.

Related to MCP-2402

Author: Dumbris

cmd/mcpproxy/security_cmd.go

@@ -1254,6 +1254,104 @@ func getMapFloat(m map[string]interface{}, key string) float64 {
 	return 0
 }
 
+// scannerDurationMs returns a scanner_statuses entry's wall-clock duration in
+// milliseconds. It prefers the explicit duration_ms field and falls back to
+// computing it from started_at/completed_at so reports produced before
+// duration_ms was recorded still render a timing value.
+func scannerDurationMs(ss map[string]interface{}) float64 {
+	if ms := getMapFloat(ss, "duration_ms"); ms > 0 {
+		return ms
+	}
+	start := getMapString(ss, "started_at")
+	end := getMapString(ss, "completed_at")
+	if start == "" || end == "" {
+		return 0
+	}
+	st, err1 := time.Parse(time.RFC3339Nano, start)
+	et, err2 := time.Parse(time.RFC3339Nano, end)
+	if err1 != nil || err2 != nil || et.Before(st) {
+		return 0
+	}
+	return float64(et.Sub(st).Milliseconds())
+}
+
+// formatScannerDurationMs renders a per-scanner duration for human-readable
+// output: sub-second values in milliseconds, larger values as a compact "X.Ys",
+// and missing/zero timing as a dash.
+func formatScannerDurationMs(ms float64) string {
+	if ms <= 0 {
+		return "-"
+	}
+	if ms < 1000 {
+		return fmt.Sprintf("%dms", int(ms))
+	}
+	return fmt.Sprintf("%.1fs", ms/1000)
+}
+
+// printScannerStatusTable renders the per-scanner execution table including a
+// DURATION column. Nothing is printed when there are no scanner statuses.
+func printScannerStatusTable(scannerStatuses []interface{}) {
+	if len(scannerStatuses) == 0 {
+		return
+	}
+	fmt.Println()
+	fmt.Printf("  %-20s %-12s %-10s %-8s %s\n", "SCANNER", "STATUS", "DURATION", "FINDINGS", "ERROR")
+	fmt.Printf("  %s\n", strings.Repeat("-", 75))
+	for _, s := range scannerStatuses {
+		ss, ok := s.(map[string]interface{})
+		if !ok {
+			continue
+		}
+		scannerID := getMapString(ss, "scanner_id")
+		ssStatus := getMapString(ss, "status")
+		findings := "0"
+		if fc, ok := ss["findings_count"].(float64); ok {
+			findings = fmt.Sprintf("%d", int(fc))
+		}
+		ssErr := getMapString(ss, "error")
+		if len(ssErr) > 25 {
+			ssErr = ssErr[:22] + "..."
+		}
+		dur := formatScannerDurationMs(scannerDurationMs(ss))
+		fmt.Printf("  %-20s %-12s %-10s %-8s %s\n", scannerID, ssStatus, dur, findings, ssErr)
+	}
+}
+
+// printScannerTimings renders a compact per-scanner wall-clock timing block
+// from a scan report's scanner_statuses. Nothing is printed when timing data
+// is absent.
+func printScannerTimings(report map[string]interface{}) {
+	statuses, ok := report["scanner_statuses"].([]interface{})
+	if !ok || len(statuses) == 0 {
+		return
+	}
+	type timingRow struct{ id, status, dur string }
+	rows := make([]timingRow, 0, len(statuses))
+	for _, s := range statuses {
+		ss, ok := s.(map[string]interface{})
+		if !ok {
+			continue
+		}
+		id := getMapString(ss, "scanner_id")
+		if id == "" {
+			continue
+		}
+		rows = append(rows, timingRow{
+			id:     id,
+			status: getMapString(ss, "status"),
+			dur:    formatScannerDurationMs(scannerDurationMs(ss)),
+		})
+	}
+	if len(rows) == 0 {
+		return
+	}
+	fmt.Println()
+	fmt.Println("Scanner timing:")
+	for _, r := range rows {
+		fmt.Printf("  %-20s %-12s %s\n", r.id, r.status, r.dur)
+	}
+}
+
 func runSecurityStatus(_ *cobra.Command, args []string) error {
 	client, _, err := newSecurityCLIClient()
 	if err != nil {
@@ -1310,26 +1408,9 @@ func runSecurityStatus(_ *cobra.Command, args []string) error {
 		fmt.Printf("  Error:    %s\n", errMsg)
 	}
 
-	// Per-scanner statuses
-	if scannerStatuses, ok := status["scanner_statuses"].([]interface{}); ok && len(scannerStatuses) > 0 {
-		fmt.Println()
-		fmt.Printf("  %-20s %-12s %-8s %s\n", "SCANNER", "STATUS", "FINDINGS", "ERROR")
-		fmt.Printf("  %s\n", strings.Repeat("-", 65))
-		for _, s := range scannerStatuses {
-			if ss, ok := s.(map[string]interface{}); ok {
-				scannerID := getMapString(ss, "scanner_id")
-				ssStatus := getMapString(ss, "status")
-				findings := "0"
-				if fc, ok := ss["findings_count"].(float64); ok {
-					findings = fmt.Sprintf("%d", int(fc))
-				}
-				ssErr := getMapString(ss, "error")
-				if len(ssErr) > 25 {
-					ssErr = ssErr[:22] + "..."
-				}
-				fmt.Printf("  %-20s %-12s %-8s %s\n", scannerID, ssStatus, findings, ssErr)
-			}
-		}
+	// Per-scanner statuses (includes a DURATION column)
+	if scannerStatuses, ok := status["scanner_statuses"].([]interface{}); ok {
+		printScannerStatusTable(scannerStatuses)
 	}
 
 	return nil
@@ -1768,6 +1849,11 @@ func printReportTable(serverName string, report map[string]interface{}, failedSc
 		fmt.Println(line)
 	}
 
+	// Per-scanner wall-clock timing, so users can see which scanner dominated
+	// the scan time. Sourced from scanner_statuses; silently skipped when the
+	// report carries no per-scanner status data.
+	printScannerTimings(report)
+
 	// Scan context: show the user what was actually scanned. Without this the
 	// terse "0 findings" / "1 finding" output gives no signal as to whether
 	// the scan looked at real source code (docker_extract), a working_dir

cmd/mcpproxy/security_cmd_test.go

@@ -329,3 +329,101 @@ func TestPrintReportTableRendersFailedScannerReasons(t *testing.T) {
 		}
 	}
 }
+
+// TestFormatScannerDurationMs verifies the per-scanner duration formatter:
+// sub-second values render in milliseconds, second-and-up values render as a
+// compact "X.Ys", and missing/zero timing renders as a dash rather than "0ms".
+func TestFormatScannerDurationMs(t *testing.T) {
+	cases := []struct {
+		ms   float64
+		want string
+	}{
+		{0, "-"},
+		{-5, "-"},
+		{850, "850ms"},
+		{999, "999ms"},
+		{1000, "1.0s"},
+		{1500, "1.5s"},
+		{12340, "12.3s"},
+	}
+	for _, c := range cases {
+		if got := formatScannerDurationMs(c.ms); got != c.want {
+			t.Errorf("formatScannerDurationMs(%v) = %q, want %q", c.ms, got, c.want)
+		}
+	}
+}
+
+// TestScannerDurationMs verifies that the explicit duration_ms field is
+// preferred, with a fallback to computing the duration from the
+// started_at/completed_at timestamps for reports produced before duration_ms
+// was recorded.
+func TestScannerDurationMs(t *testing.T) {
+	// Explicit duration_ms wins.
+	if got := scannerDurationMs(map[string]interface{}{"duration_ms": float64(1200)}); got != 1200 {
+		t.Errorf("expected 1200 from explicit duration_ms, got %v", got)
+	}
+	// Fallback: compute from timestamps when duration_ms is absent.
+	got := scannerDurationMs(map[string]interface{}{
+		"started_at":   "2026-06-14T10:00:00Z",
+		"completed_at": "2026-06-14T10:00:02Z",
+	})
+	if got != 2000 {
+		t.Errorf("expected 2000 from timestamp fallback, got %v", got)
+	}
+	// No timing data → 0.
+	if got := scannerDurationMs(map[string]interface{}{"scanner_id": "x"}); got != 0 {
+		t.Errorf("expected 0 with no timing, got %v", got)
+	}
+}
+
+// TestPrintScannerStatusTableRendersDuration verifies the per-scanner status
+// table gained a DURATION column populated from each scanner's timing.
+func TestPrintScannerStatusTableRendersDuration(t *testing.T) {
+	out := captureStdout(t, func() {
+		printScannerStatusTable([]interface{}{
+			map[string]interface{}{
+				"scanner_id":     "mcp-scan",
+				"status":         "completed",
+				"findings_count": float64(2),
+				"duration_ms":    float64(1500),
+			},
+			map[string]interface{}{
+				"scanner_id":   "trivy-mcp",
+				"status":       "completed",
+				"started_at":   "2026-06-14T10:00:00Z",
+				"completed_at": "2026-06-14T10:00:03Z",
+			},
+		})
+	})
+	for _, w := range []string{"DURATION", "mcp-scan", "1.5s", "trivy-mcp", "3.0s"} {
+		if !strings.Contains(out, w) {
+			t.Errorf("status table missing %q\n--- output ---\n%s", w, out)
+		}
+	}
+}
+
+// TestPrintReportTableRendersScannerTimings verifies the scan report renders a
+// per-scanner timing block sourced from scanner_statuses.
+func TestPrintReportTableRendersScannerTimings(t *testing.T) {
+	report := map[string]interface{}{
+		"job_id":     "scan-foo-1",
+		"risk_score": float64(0),
+		"scanned_at": "2026-04-26T17:39:05Z",
+		"findings":   []interface{}{},
+		"scanner_statuses": []interface{}{
+			map[string]interface{}{
+				"scanner_id":  "mcp-scan",
+				"status":      "completed",
+				"duration_ms": float64(1200),
+			},
+		},
+	}
+	out := captureStdout(t, func() {
+		_ = printReportTable("foo", report, nil)
+	})
+	for _, w := range []string{"Scanner timing:", "mcp-scan", "1.2s"} {
+		if !strings.Contains(out, w) {
+			t.Errorf("report missing %q\n--- output ---\n%s", w, out)
+		}
+	}
+}

docs/cli/security-commands.md

@@ -297,6 +297,11 @@ Risk Score:  0/100
 Scanned:     2026-04-10 10:08:19
 Scanners:    6 run, 1 failed (ramparts) of 7
 
+Scanner timing:
+  mcp-scan             completed    1.2s
+  trivy-mcp            completed    12.3s
+  ramparts             failed       -
+
 WARNING: Scan coverage incomplete: 1 of 7 scanners did not run
 
 === Security Scan (Pass 1) ===
@@ -421,17 +426,19 @@ Scan Status: everything
   Started:  2026-04-10 08:41:17
   Finished: 2026-04-10 08:42:09
 
-  SCANNER              STATUS       FINDINGS ERROR
-  -----------------------------------------------------------------
-  cisco-mcp-scanner    completed    0
-  mcp-ai-scanner       completed    0
-  mcp-scan             failed       0        scanner mcp-scan produ...
-  nova-proximity       completed    0
-  ramparts             failed       0        scanner ramparts produ...
-  semgrep-mcp          completed    0
-  trivy-mcp            completed    0
+  SCANNER              STATUS       DURATION   FINDINGS ERROR
+  ---------------------------------------------------------------------------
+  cisco-mcp-scanner    completed    1.2s       0
+  mcp-ai-scanner       completed    3.4s       0
+  mcp-scan             failed       850ms      0        scanner mcp-scan produ...
+  nova-proximity       completed    2.1s       0
+  ramparts             failed       120ms      0        scanner ramparts produ...
+  semgrep-mcp          completed    5.7s       0
+  trivy-mcp            completed    12.3s      0
 ```
 
+The `DURATION` column is each scanner's wall-clock execution time, computed from its `started_at`/`completed_at` timestamps. It renders `-` when timing is unavailable (e.g. a scanner that never started).
+
 :::tip Use status for diagnostics
 If `security report` shows "0 findings" but you think a scanner should have flagged something, open `status` — failed scanners appear here with their truncated stderr. The full stderr is available via `security status <server> -o json`.
 :::
@@ -469,6 +476,11 @@ Risk Score:  0/100
 Scanned:     2026-04-10 10:08:19
 Scanners:    6 run, 1 failed (ramparts) of 7
 
+Scanner timing:
+  mcp-scan             completed    1.2s
+  trivy-mcp            completed    12.3s
+  ramparts             failed       -
+
 WARNING: Scan coverage incomplete: 1 of 7 scanners did not run
 
 === Security Scan (Pass 1) ===
@@ -488,6 +500,7 @@ The `Scanners: X run, Y failed (names) of Z` line surfaces per-scanner failures
 - `summary` — severity counts (`critical`, `high`, `medium`, `low`, `info`, `dangerous`, `warnings`, `info_level`, `total`)
 - `findings` — normalized findings across all scanners
 - `reports` — per-scanner raw results (also includes SARIF when `?include_sarif=true` is passed to the REST endpoint)
+- `scanner_statuses` — per-scanner execution records, each with `scanner_id`, `status`, `started_at`, `completed_at`, `duration_ms` (wall-clock execution time in milliseconds), `findings_count`, and `error`
 - `scan_context` — source method, source path, scanned file list
 - `scanners_run`, `scanners_failed`, `scanners_total`
 - `pass1_complete`, `pass2_complete`, `pass2_running`

internal/security/scanner/engine.go

@@ -675,6 +675,10 @@ func (e *Engine) updateScannerStatus(job *ScanJob, scannerID, status string, sta
 			}
 			job.ScannerStatuses[i].Error = errMsg
 			job.ScannerStatuses[i].FindingsCount = findingsCount
+			// Recompute duration once both timestamps are known. The live scan
+			// path sets StartedAt and CompletedAt in separate calls, so this
+			// derives from the stored StartedAt when CompletedAt arrives.
+			job.ScannerStatuses[i].DurationMs = job.ScannerStatuses[i].Duration().Milliseconds()
 			return
 		}
 	}

internal/security/scanner/scanner_duration_test.go

@@ -0,0 +1,75 @@
+package scanner
+
+import (
+	"testing"
+	"time"
+
+	"go.uber.org/zap"
+)
+
+// TestScannerJobStatusDuration verifies per-scanner wall-clock computation,
+// including the degenerate cases (still running, never started, clock skew)
+// where we must report 0 rather than a negative or bogus value.
+func TestScannerJobStatusDuration(t *testing.T) {
+	start := time.Date(2026, 6, 14, 10, 0, 0, 0, time.UTC)
+	tests := []struct {
+		name   string
+		status ScannerJobStatus
+		wantMs int64
+	}{
+		{
+			name:   "normal duration",
+			status: ScannerJobStatus{StartedAt: start, CompletedAt: start.Add(1500 * time.Millisecond)},
+			wantMs: 1500,
+		},
+		{
+			name:   "never started",
+			status: ScannerJobStatus{CompletedAt: start},
+			wantMs: 0,
+		},
+		{
+			name:   "still running",
+			status: ScannerJobStatus{StartedAt: start},
+			wantMs: 0,
+		},
+		{
+			name:   "completed before started (clock skew)",
+			status: ScannerJobStatus{StartedAt: start, CompletedAt: start.Add(-time.Second)},
+			wantMs: 0,
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			if got := tt.status.Duration().Milliseconds(); got != tt.wantMs {
+				t.Errorf("Duration() = %d ms, want %d ms", got, tt.wantMs)
+			}
+		})
+	}
+}
+
+// TestUpdateScannerStatusComputesDurationMs guards that DurationMs is populated
+// as soon as both timestamps are known. The live scan path sets StartedAt and
+// CompletedAt in two separate updateScannerStatus calls, so the duration must
+// be recomputed from the stored StartedAt when CompletedAt arrives.
+func TestUpdateScannerStatusComputesDurationMs(t *testing.T) {
+	engine := NewEngine(nil, nil, t.TempDir(), zap.NewNop())
+	job := &ScanJob{
+		ID: "job-1",
+		ScannerStatuses: []ScannerJobStatus{
+			{ScannerID: "scanner-a", Status: ScanJobStatusPending},
+		},
+	}
+	start := time.Now()
+
+	// Running: only StartedAt is set; CompletedAt stays zero → no duration yet.
+	engine.updateScannerStatus(job, "scanner-a", ScanJobStatusRunning, start, time.Time{}, "", 0)
+	if got := job.ScannerStatuses[0].DurationMs; got != 0 {
+		t.Fatalf("DurationMs = %d while running, want 0", got)
+	}
+
+	// Completed: CompletedAt set; duration computed from the stored StartedAt.
+	engine.updateScannerStatus(job, "scanner-a", ScanJobStatusCompleted, time.Time{}, start.Add(2*time.Second), "", 3)
+	if got := job.ScannerStatuses[0].DurationMs; got != 2000 {
+		t.Errorf("DurationMs = %d, want 2000", got)
+	}
+}