fix(copilot): use execution events for tool timing (#1290)

Copilot CLI records authoritative `tool.execution_start` and `tool.execution_complete` timestamps, but Session Analysis currently derives completed call duration from the next persisted message. Resuming a session hours later can therefore attribute the entire idle gap to the final tool call.

This change preserves Copilot execution boundaries as canonical tool-result events and uses paired start/completion timestamps for per-call timing in SQLite, PostgreSQL, and DuckDB. When every call in a turn has an authoritative completion boundary, the turn ends at the latest completion instead of the next user message; incomplete and unsupported providers retain the existing fallback behavior.

Blocked result categories continue to omit result content while retaining non-content execution metadata needed for timing. The parser data version advances so existing source-backed Copilot sessions are rebuilt with execution events. The Copilot format inventory records the observed event contract, and focused parser, ingestion, and timing regressions cover a completed blocked Read call followed by a 12-hour resumed-session gap.

The main review points are the result-event representation in `internal/parser/copilot.go`, blocked-content handling in `internal/sync/engine.go`, the fallback boundary rules in `internal/db/timing.go`, and storage-backend query parity.

Fixes #1288

Co-authored-by: Christina7 <Christina7@users.noreply.github.com>

Author: Christina7

docs/internal/session-format-sources.md

@@ -221,7 +221,11 @@ Grok section and remove the explicit registry exception in the coverage test.
   cache-write, and reasoning tokens. Copilot accounting is credit-oriented;
   Agentsview does not treat credits as USD and does not infer a monetary cost.
 - **Agentsview:** `internal/parser/copilot.go` and
-  `internal/parser/copilot_provider.go`.
+  `internal/parser/copilot_provider.go`. Reverified 2026-07-28 against local
+  Copilot CLI 1.0.76-0 transcripts: `tool.execution_start` and
+  `tool.execution_complete` carry the same `data.toolCallId` and independent
+  RFC3339 `timestamp` values, providing an exact execution interval even when
+  the next user message arrives after a long resumed-session idle gap.
 
 ## Gemini CLI (`gemini`)
 

internal/db/db.go

@@ -339,7 +339,10 @@ const projectIdentityRemoteScrubCompletedKey = "project_identity_remote_scrub_v1
 // instead of the generated checkout leaf, and generic hosting fragments defer
 // to an enclosing live repository. Existing rows need re-parsing so activity
 // is neither fragmented by worktree names nor claimed by nested fixture paths.)
-const dataVersion = 75
+// (76: Copilot CLI tool execution boundaries. Re-parsing persists
+// tool.execution_start and tool.execution_complete timestamps as result events
+// so Session Analysis excludes resumed-session idle time from completed calls.)
+const dataVersion = 76
 
 const tokenCoverageRepairStatsKey = "token_coverage_repair_v1"
 

internal/db/db_test.go

@@ -1008,9 +1008,9 @@ func TestMigration_ToolResultEventsTable(t *testing.T) {
 		"expected tool_result_events table after reopen")
 }
 
-func TestCurrentDataVersionGitWorktreeProjectAttribution(t *testing.T) {
-	assert.Equal(t, 75, CurrentDataVersion(),
-		"final git worktree project attribution requires a data version bump")
+func TestCurrentDataVersionCopilotToolTiming(t *testing.T) {
+	assert.Equal(t, 76, CurrentDataVersion(),
+		"Copilot tool execution timing requires a data version bump")
 }
 
 func TestInsertMessages_PreservesToolResultEvents(t *testing.T) {

internal/db/timing.go

@@ -74,6 +74,7 @@ type CallRow struct {
 	SubagentSessionID *string
 	InputJSON         string
 	DurationMs        *int64
+	CompletedAt       string
 }
 
 // GetSessionTiming computes the per-session timing summary. Returns
@@ -173,6 +174,30 @@ func (db *DB) queryCallRows(
 		  tc.skill_name,
 		  tc.subagent_session_id,
 		  tc.input_json,
+		  (
+		    SELECT tre.timestamp
+		    FROM tool_result_events tre
+		    WHERE tre.session_id = tc.session_id
+		      AND tre.tool_call_message_ordinal = m.ordinal
+		      AND tre.call_index = tc.call_index
+		      AND tre.source = 'tool_execution'
+		      AND tre.status = 'started'
+		      AND NULLIF(tre.timestamp, '') IS NOT NULL
+		    ORDER BY tre.event_index ASC
+		    LIMIT 1
+		  ) AS execution_started_at,
+		  (
+		    SELECT tre.timestamp
+		    FROM tool_result_events tre
+		    WHERE tre.session_id = tc.session_id
+		      AND tre.tool_call_message_ordinal = m.ordinal
+		      AND tre.call_index = tc.call_index
+		      AND tre.source = 'tool_execution'
+		      AND tre.status IN ('completed', 'errored')
+		      AND NULLIF(tre.timestamp, '') IS NOT NULL
+		    ORDER BY tre.event_index DESC
+		    LIMIT 1
+		  ) AS execution_completed_at,
 		  CASE
 		    WHEN tc.subagent_session_id IS NOT NULL
 		         AND s_sub.started_at IS NOT NULL THEN
@@ -185,6 +210,7 @@ func (db *DB) queryCallRows(
 		    ELSE NULL
 		  END AS subagent_duration_ms
 		FROM tool_calls tc
+		JOIN messages m ON m.id = tc.message_id
 		LEFT JOIN sessions s_sub
 		  ON s_sub.id = tc.subagent_session_id
 		WHERE tc.session_id = ?
@@ -199,11 +225,12 @@ func (db *DB) queryCallRows(
 	for rows.Next() {
 		var r CallRow
 		var toolUseID, inputJSON sql.NullString
-		var skill, sub sql.NullString
+		var skill, sub, executionStarted, executionCompleted sql.NullString
 		var subDur sql.NullInt64
 		if err := rows.Scan(
 			&r.MessageID, &toolUseID, &r.ToolName, &r.Category,
-			&skill, &sub, &inputJSON, &subDur,
+			&skill, &sub, &inputJSON, &executionStarted, &executionCompleted,
+			&subDur,
 		); err != nil {
 			return nil, err
 		}
@@ -224,6 +251,12 @@ func (db *DB) queryCallRows(
 		if subDur.Valid {
 			v := subDur.Int64
 			r.DurationMs = &v
+		} else if executionStarted.Valid && executionCompleted.Valid {
+			v := millisBetween(executionStarted.String, executionCompleted.String)
+			if v >= 0 {
+				r.DurationMs = &v
+				r.CompletedAt = executionCompleted.String
+			}
 		}
 		out = append(out, r)
 	}
@@ -287,6 +320,13 @@ func AssembleTiming(
 			turnCalls = []CallTiming{}
 		}
 
+		if completedAt, ok := completedCallBoundary(calls, t.MessageID); ok {
+			v := millisBetween(t.Timestamp, completedAt)
+			if v >= 0 {
+				t.DurationMs = &v
+			}
+		}
+
 		for i := range turnCalls {
 			turnCalls[i].IsParallel = len(turnCalls) > 1
 			// Solo non-sub-agent: propagate the turn's duration to the
@@ -347,6 +387,24 @@ func AssembleTiming(
 	return out
 }
 
+func completedCallBoundary(calls []CallRow, messageID int64) (string, bool) {
+	var boundary string
+	matched := 0
+	for _, call := range calls {
+		if call.MessageID != messageID {
+			continue
+		}
+		matched++
+		if call.CompletedAt == "" {
+			return "", false
+		}
+		if boundary == "" || millisBetween(boundary, call.CompletedAt) > 0 {
+			boundary = call.CompletedAt
+		}
+	}
+	return boundary, matched > 0
+}
+
 // turnAttribution is the result of attributeTurnGo. RemainderMs is the
 // portion of the turn's duration attributed to PrimaryCategory after
 // subtracting the union of any sub-agent durations. SubagentDurations

internal/db/timing_test.go

@@ -25,6 +25,22 @@ func TestGetSessionTiming_ReadOnlyFixture(t *testing.T) {
 	timingInsertMessage(t, d, "solo", 2, "user",
 		"ok", "2026-04-26T10:00:30Z", false)
 
+	timingInsertSession(t, d, "completed-call",
+		"2026-04-26T10:00:00Z", "2026-04-26T22:38:05Z")
+	timingInsertMessage(t, d, "completed-call", 0, "user",
+		"run", "2026-04-26T10:00:00Z", false)
+	timingInsertMessage(t, d, "completed-call", 1, "assistant",
+		"finishing", "2026-04-26T10:00:01Z", true)
+	completedCallMsgID := timingMsgID(t, d, "completed-call", 1)
+	timingInsertToolCall(t, d, "completed-call", completedCallMsgID,
+		"tu_done", "task_complete", "Other", "")
+	timingInsertToolResultEvent(t, d, "completed-call", 1, 0,
+		"tu_done", "started", "2026-04-26T10:00:01.100Z", 0)
+	timingInsertToolResultEvent(t, d, "completed-call", 1, 0,
+		"tu_done", "completed", "2026-04-26T10:00:04.825Z", 1)
+	timingInsertMessage(t, d, "completed-call", 2, "user",
+		"next request", "2026-04-26T22:38:05Z", false)
+
 	timingInsertSession(t, d, "fallback",
 		"2026-04-26T10:00:00Z", "2026-04-26T10:00:30Z")
 	timingInsertMessage(t, d, "fallback", 0, "user",
@@ -112,6 +128,23 @@ func TestGetSessionTiming_ReadOnlyFixture(t *testing.T) {
 		assert.Equal(t, int64(29_000), *got.Turns[0].Calls[0].DurationMs, "call duration")
 	})
 
+	t.Run("completed call excludes idle time before next user message", func(t *testing.T) {
+		got, err := d.GetSessionTiming(ctx, "completed-call")
+		require.NoError(t, err, "GetSessionTiming")
+		require.Len(t, got.Turns, 1)
+		require.Len(t, got.Turns[0].Calls, 1)
+		require.NotNil(t, got.Turns[0].DurationMs)
+		assert.Equal(t, int64(3_825), *got.Turns[0].DurationMs)
+		require.NotNil(t, got.Turns[0].Calls[0].DurationMs)
+		assert.Equal(t, int64(3_725), *got.Turns[0].Calls[0].DurationMs)
+		assert.Equal(t, int64(3_825), got.ToolDurationMs)
+		require.NotNil(t, got.SlowestCall)
+		assert.Equal(t, "task_complete", got.SlowestCall.ToolName)
+		assert.Equal(t, int64(3_725), *got.SlowestCall.DurationMs)
+		require.Len(t, got.ByCategory, 1)
+		assert.Equal(t, int64(3_825), got.ByCategory[0].DurationMs)
+	})
+
 	t.Run("last message falls back to session end", func(t *testing.T) {
 		got, err := d.GetSessionTiming(ctx, "fallback")
 		require.NoError(t, err, "GetSessionTiming")
@@ -343,8 +376,24 @@ func timingInsertToolCall(
 	_, err := d.getWriter().ExecContext(context.Background(), `
 		INSERT INTO tool_calls
 			(session_id, message_id, tool_use_id, tool_name,
-			 category, input_json, subagent_session_id)
-		VALUES (?, ?, ?, ?, ?, '{}', ?)
+			 category, input_json, subagent_session_id, call_index)
+		VALUES (?, ?, ?, ?, ?, '{}', ?, 0)
 	`, sessionID, messageID, toolUseID, toolName, category, sub)
 	require.NoError(t, err, "timingInsertToolCall %s/%d", sessionID, messageID)
 }
+
+func timingInsertToolResultEvent(
+	t *testing.T, d *DB, sessionID string, messageOrdinal, callIndex int,
+	toolUseID, status, timestamp string, eventIndex int,
+) {
+	t.Helper()
+	_, err := d.getWriter().ExecContext(context.Background(), `
+		INSERT INTO tool_result_events
+			(session_id, tool_call_message_ordinal, call_index,
+			 tool_use_id, source, status, content, timestamp, event_index)
+		VALUES (?, ?, ?, ?, 'tool_execution', ?, '', ?, ?)
+	`, sessionID, messageOrdinal, callIndex, toolUseID, status, timestamp,
+		eventIndex)
+	require.NoError(t, err, "timingInsertToolResultEvent %s/%d", sessionID,
+		eventIndex)
+}

internal/duckdb/messages.go

@@ -525,8 +525,33 @@ func (s *Store) queryCallRows(
 		SELECT tc.message_id, COALESCE(tc.tool_use_id, ''),
 			tc.tool_name, tc.category, tc.skill_name,
 			tc.subagent_session_id, COALESCE(tc.input_json, ''),
+			(
+				SELECT tre.timestamp
+				FROM tool_result_events tre
+				WHERE tre.session_id = tc.session_id
+					AND tre.tool_call_message_ordinal = m.ordinal
+					AND tre.call_index = tc.call_index
+					AND tre.source = 'tool_execution'
+					AND tre.status = 'started'
+					AND tre.timestamp IS NOT NULL
+				ORDER BY tre.event_index ASC
+				LIMIT 1
+			) AS execution_started_at,
+			(
+				SELECT tre.timestamp
+				FROM tool_result_events tre
+				WHERE tre.session_id = tc.session_id
+					AND tre.tool_call_message_ordinal = m.ordinal
+					AND tre.call_index = tc.call_index
+					AND tre.source = 'tool_execution'
+					AND tre.status IN ('completed', 'errored')
+					AND tre.timestamp IS NOT NULL
+				ORDER BY tre.event_index DESC
+				LIMIT 1
+			) AS execution_completed_at,
 			s_sub.started_at, s_sub.ended_at
 		FROM tool_calls tc
+		JOIN messages m ON m.id = tc.message_id
 		LEFT JOIN sessions s_sub ON s_sub.id = tc.subagent_session_id
 		WHERE tc.session_id = ?
 		ORDER BY tc.message_id, tc.call_index`,
@@ -542,10 +567,11 @@ func (s *Store) queryCallRows(
 	for rows.Next() {
 		var r db.CallRow
 		var skill, sub sql.NullString
-		var startedAt, endedAt any
+		var executionStarted, executionCompleted, startedAt, endedAt any
 		if err := rows.Scan(
 			&r.MessageID, &r.ToolUseID, &r.ToolName, &r.Category,
-			&skill, &sub, &r.InputJSON, &startedAt, &endedAt,
+			&skill, &sub, &r.InputJSON, &executionStarted, &executionCompleted,
+			&startedAt, &endedAt,
 		); err != nil {
 			return nil, fmt.Errorf("scanning duckdb timing call: %w", err)
 		}
@@ -559,6 +585,11 @@ func (s *Store) queryCallRows(
 			if dur, ok := timingMillis(formatDBTime(startedAt), firstNonEmpty(formatDBTime(endedAt), now)); ok {
 				r.DurationMs = &dur
 			}
+		} else if completedAt := formatDBTime(executionCompleted); completedAt != "" {
+			if dur, ok := timingMillis(formatDBTime(executionStarted), completedAt); ok {
+				r.DurationMs = &dur
+				r.CompletedAt = completedAt
+			}
 		}
 		out = append(out, r)
 	}

internal/duckdb/store_test.go

@@ -1623,8 +1623,8 @@ func TestGetSessionTimingPopulatesSharedTimingPayload(t *testing.T) {
 	local := newLocalDB(t)
 	sessionID := "duck-timing"
 	startedAt := "2026-01-20T00:00:00.000Z"
-	endedAt := "2026-01-20T00:03:00.000Z"
-	sess := syncSession(sessionID, "alpha", "timing first", startedAt, 2)
+	endedAt := "2026-01-20T12:38:06.000Z"
+	sess := syncSession(sessionID, "alpha", "timing first", startedAt, 3)
 	sess.EndedAt = &endedAt
 	_, err := local.WriteSessionBatchAtomic([]db.SessionBatchWrite{{
 		Session: sess,
@@ -1636,7 +1636,22 @@ func TestGetSessionTimingPopulatesSharedTimingPayload(t *testing.T) {
 					Category:  "Read",
 					ToolUseID: "tool-timing",
 					InputJSON: `{"file_path":"README.md"}`,
+					ResultEvents: []db.ToolResultEvent{
+						{
+							ToolUseID: "tool-timing",
+							Source:    "tool_execution",
+							Status:    "started",
+							Timestamp: "2026-01-20T00:01:00.100Z",
+						},
+						{
+							ToolUseID: "tool-timing",
+							Source:    "tool_execution",
+							Status:    "completed",
+							Timestamp: "2026-01-20T00:01:03.825Z",
+						},
+					},
 				}),
+			syncMessage(sessionID, 2, "user", "next request", "2026-01-20T12:38:05.000Z"),
 		},
 		DataVersion:     1,
 		ReplaceMessages: true,
@@ -1653,17 +1668,17 @@ func TestGetSessionTimingPopulatesSharedTimingPayload(t *testing.T) {
 	require.NoError(t, err)
 	require.NotNil(t, timing)
 	assert.Equal(t, sessionID, timing.SessionID)
-	assert.Equal(t, int64(180000), timing.TotalDurationMs)
+	assert.Equal(t, int64(45_486_000), timing.TotalDurationMs)
 	assert.Equal(t, 1, timing.TurnCount)
 	assert.Equal(t, 1, timing.ToolCallCount)
 	assert.False(t, timing.Running)
 	require.Len(t, timing.Turns, 1)
 	assert.Equal(t, 1, timing.Turns[0].Ordinal)
 	require.NotNil(t, timing.Turns[0].DurationMs)
-	assert.Equal(t, int64(120000), *timing.Turns[0].DurationMs)
+	assert.Equal(t, int64(3_825), *timing.Turns[0].DurationMs)
 	require.Len(t, timing.Turns[0].Calls, 1)
 	require.NotNil(t, timing.Turns[0].Calls[0].DurationMs)
-	assert.Equal(t, int64(120000), *timing.Turns[0].Calls[0].DurationMs)
+	assert.Equal(t, int64(3_725), *timing.Turns[0].Calls[0].DurationMs)
 }
 
 func TestGetAllMessagesDoesNotTruncateAtDefaultLimit(t *testing.T) {