From 71f706cf29cf70a888ee65117b21ad31042207f8 Mon Sep 17 00:00:00 2001 From: Richie Foreman Date: Mon, 18 Aug 2025 15:59:13 -0400 Subject: [PATCH] feat(client/compression): Log telemetry when compressing chat context. (#6195) --- docs/telemetry.md | 5 + packages/core/src/core/client.test.ts | 40 ++++ packages/core/src/core/client.ts | 54 ++++-- .../clearcut-logger/clearcut-logger.test.ts | 181 +++++++++++++----- .../clearcut-logger/clearcut-logger.ts | 85 ++++---- .../clearcut-logger/event-metadata-key.ts | 15 +- packages/core/src/telemetry/constants.ts | 2 +- packages/core/src/telemetry/index.ts | 3 + .../telemetry/integration.test.circular.ts | 3 +- packages/core/src/telemetry/loggers.test.ts | 43 +++++ packages/core/src/telemetry/loggers.ts | 28 +++ packages/core/src/telemetry/metrics.test.ts | 50 ++++- packages/core/src/telemetry/metrics.ts | 17 ++ packages/core/src/telemetry/types.ts | 23 ++- 14 files changed, 426 insertions(+), 123 deletions(-) diff --git a/docs/telemetry.md b/docs/telemetry.md index 6767e349..ed094ce6 100644 --- a/docs/telemetry.md +++ b/docs/telemetry.md @@ -271,3 +271,8 @@ Metrics are numerical measurements of behavior over time. The following metrics - `ai_removed_lines` (Int, if applicable): Number of lines removed/changed by AI. - `user_added_lines` (Int, if applicable): Number of lines added/changed by user in AI proposed changes. - `user_removed_lines` (Int, if applicable): Number of lines removed/changed by user in AI proposed changes. + +- `gemini_cli.chat_compression` (Counter, Int): Counts chat compression operations + - **Attributes**: + - `tokens_before`: (Int): Number of tokens in context prior to compression + - `tokens_after`: (Int): Number of tokens in context after compression diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 6fecd676..5afdba55 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -24,6 +24,7 @@ import { FileDiscoveryService } from '../services/fileDiscoveryService.js'; import { setSimulate429 } from '../utils/testUtils.js'; import { tokenLimit } from './tokenLimits.js'; import { ideContext } from '../ide/ideContext.js'; +import { ClearcutLogger } from '../telemetry/clearcut-logger/clearcut-logger.js'; // --- Mocks --- const mockChatCreateFn = vi.fn(); @@ -532,6 +533,45 @@ describe('Gemini Client (client.ts)', () => { expect(newChat).toBe(initialChat); }); + it('logs a telemetry event when compressing', async () => { + vi.spyOn(ClearcutLogger.prototype, 'logChatCompressionEvent'); + + const MOCKED_TOKEN_LIMIT = 1000; + const MOCKED_CONTEXT_PERCENTAGE_THRESHOLD = 0.5; + vi.mocked(tokenLimit).mockReturnValue(MOCKED_TOKEN_LIMIT); + vi.spyOn(client['config'], 'getChatCompression').mockReturnValue({ + contextPercentageThreshold: MOCKED_CONTEXT_PERCENTAGE_THRESHOLD, + }); + mockGetHistory.mockReturnValue([ + { role: 'user', parts: [{ text: '...history...' }] }, + ]); + + const originalTokenCount = + MOCKED_TOKEN_LIMIT * MOCKED_CONTEXT_PERCENTAGE_THRESHOLD; + const newTokenCount = 100; + + mockCountTokens + .mockResolvedValueOnce({ totalTokens: originalTokenCount }) // First call for the check + .mockResolvedValueOnce({ totalTokens: newTokenCount }); // Second call for the new history + + // Mock the summary response from the chat + mockSendMessage.mockResolvedValue({ + role: 'model', + parts: [{ text: 'This is a summary.' }], + }); + + await client.tryCompressChat('prompt-id-3'); + + expect( + ClearcutLogger.prototype.logChatCompressionEvent, + ).toHaveBeenCalledWith( + expect.objectContaining({ + tokens_before: originalTokenCount, + tokens_after: newTokenCount, + }), + ); + }); + it('should trigger summarization if token count is at threshold with contextPercentageThreshold setting', async () => { const MOCKED_TOKEN_LIMIT = 1000; const MOCKED_CONTEXT_PERCENTAGE_THRESHOLD = 0.5; diff --git a/packages/core/src/core/client.ts b/packages/core/src/core/client.ts index 66f3e08f..89c194a4 100644 --- a/packages/core/src/core/client.ts +++ b/packages/core/src/core/client.ts @@ -43,8 +43,12 @@ import { ProxyAgent, setGlobalDispatcher } from 'undici'; import { DEFAULT_GEMINI_FLASH_MODEL } from '../config/models.js'; import { LoopDetectionService } from '../services/loopDetectionService.js'; import { ideContext } from '../ide/ideContext.js'; -import { logNextSpeakerCheck } from '../telemetry/loggers.js'; import { + logChatCompression, + logNextSpeakerCheck, +} from '../telemetry/loggers.js'; +import { + makeChatCompressionEvent, MalformedJsonResponseEvent, NextSpeakerCheckEvent, } from '../telemetry/types.js'; @@ -89,6 +93,20 @@ export function findIndexAfterFraction( return contentLengths.length; } +const MAX_TURNS = 100; + +/** + * Threshold for compression token count as a fraction of the model's token limit. + * If the chat history exceeds this threshold, it will be compressed. + */ +const COMPRESSION_TOKEN_THRESHOLD = 0.7; + +/** + * The fraction of the latest chat history to keep. A value of 0.3 + * means that only the last 30% of the chat history will be kept after compression. + */ +const COMPRESSION_PRESERVE_THRESHOLD = 0.3; + export class GeminiClient { private chat?: GeminiChat; private contentGenerator?: ContentGenerator; @@ -98,17 +116,6 @@ export class GeminiClient { topP: 1, }; private sessionTurnCount = 0; - private readonly MAX_TURNS = 100; - /** - * Threshold for compression token count as a fraction of the model's token limit. - * If the chat history exceeds this threshold, it will be compressed. - */ - private readonly COMPRESSION_TOKEN_THRESHOLD = 0.7; - /** - * The fraction of the latest chat history to keep. A value of 0.3 - * means that only the last 30% of the chat history will be kept after compression. - */ - private readonly COMPRESSION_PRESERVE_THRESHOLD = 0.3; private readonly loopDetector: LoopDetectionService; private lastPromptId: string; @@ -438,7 +445,7 @@ export class GeminiClient { request: PartListUnion, signal: AbortSignal, prompt_id: string, - turns: number = this.MAX_TURNS, + turns: number = MAX_TURNS, originalModel?: string, ): AsyncGenerator { if (this.lastPromptId !== prompt_id) { @@ -454,7 +461,7 @@ export class GeminiClient { return new Turn(this.getChat(), prompt_id); } // Ensure turns never exceeds MAX_TURNS to prevent infinite loops - const boundedTurns = Math.min(turns, this.MAX_TURNS); + const boundedTurns = Math.min(turns, MAX_TURNS); if (!boundedTurns) { return new Turn(this.getChat(), prompt_id); } @@ -673,7 +680,7 @@ export class GeminiClient { const userMemory = this.config.getUserMemory(); const systemInstruction = getCoreSystemPrompt(userMemory); - const requestConfig = { + const requestConfig: GenerateContentConfig = { abortSignal, ...configToUse, systemInstruction, @@ -779,7 +786,7 @@ export class GeminiClient { // Don't compress if not forced and we are under the limit. if (!force) { const threshold = - contextPercentageThreshold ?? this.COMPRESSION_TOKEN_THRESHOLD; + contextPercentageThreshold ?? COMPRESSION_TOKEN_THRESHOLD; if (originalTokenCount < threshold * tokenLimit(model)) { return null; } @@ -787,7 +794,7 @@ export class GeminiClient { let compressBeforeIndex = findIndexAfterFraction( curatedHistory, - 1 - this.COMPRESSION_PRESERVE_THRESHOLD, + 1 - COMPRESSION_PRESERVE_THRESHOLD, ); // Find the first user message after the index. This is the start of the next turn. while ( @@ -838,6 +845,14 @@ export class GeminiClient { return null; } + logChatCompression( + this.config, + makeChatCompressionEvent({ + tokens_before: originalTokenCount, + tokens_after: newTokenCount, + }), + ); + return { originalTokenCount, newTokenCount, @@ -891,3 +906,8 @@ export class GeminiClient { return null; } } + +export const TEST_ONLY = { + COMPRESSION_PRESERVE_THRESHOLD, + COMPRESSION_TOKEN_THRESHOLD, +}; diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts index f2ce4d19..39596616 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts @@ -4,6 +4,7 @@ * SPDX-License-Identifier: Apache-2.0 */ +import 'vitest'; import { vi, describe, @@ -13,8 +14,13 @@ import { beforeAll, afterAll, } from 'vitest'; - -import { ClearcutLogger, LogEventEntry, TEST_ONLY } from './clearcut-logger.js'; +import { + ClearcutLogger, + LogEvent, + LogEventEntry, + EventNames, + TEST_ONLY, +} from './clearcut-logger.js'; import { ConfigParameters } from '../../config/config.js'; import * as userAccount from '../../utils/user_account.js'; import * as userId from '../../utils/user_id.js'; @@ -22,6 +28,48 @@ import { EventMetadataKey } from './event-metadata-key.js'; import { makeFakeConfig } from '../../test-utils/config.js'; import { http, HttpResponse } from 'msw'; import { server } from '../../mocks/msw.js'; +import { makeChatCompressionEvent } from '../types.js'; + +interface CustomMatchers { + toHaveMetadataValue: ([key, value]: [EventMetadataKey, string]) => R; + toHaveEventName: (name: EventNames) => R; +} + +declare module 'vitest' { + // eslint-disable-next-line @typescript-eslint/no-explicit-any, @typescript-eslint/no-empty-object-type + interface Matchers extends CustomMatchers {} +} + +expect.extend({ + toHaveEventName(received: LogEventEntry[], name: EventNames) { + const { isNot } = this; + const event = JSON.parse(received[0].source_extension_json) as LogEvent; + const pass = event.event_name === (name as unknown as string); + return { + pass, + message: () => + `event name ${event.event_name} does${isNot ? ' not ' : ''} match ${name}}`, + }; + }, + + toHaveMetadataValue( + received: LogEventEntry[], + [key, value]: [EventMetadataKey, string], + ) { + const { isNot } = this; + const event = JSON.parse(received[0].source_extension_json) as LogEvent; + const metadata = event['event_metadata'][0]; + const data = metadata.find((m) => m.gemini_cli_key === key)?.value; + + const pass = data !== undefined && data === value; + + return { + pass, + message: () => + `event ${received} does${isNot ? ' not' : ''} have ${value}}`, + }; + }, +}); vi.mock('../../utils/user_account'); vi.mock('../../utils/user_id'); @@ -47,6 +95,7 @@ describe('ClearcutLogger', () => { const CLEARCUT_URL = 'https://play.googleapis.com/log'; const MOCK_DATE = new Date('2025-01-02T00:00:00.000Z'); const EXAMPLE_RESPONSE = `["${NEXT_WAIT_MS}",null,[[["ANDROID_BACKUP",0],["BATTERY_STATS",0],["SMART_SETUP",0],["TRON",0]],-3334737594024971225],[]]`; + // A helper to get the internal events array for testing const getEvents = (l: ClearcutLogger): LogEventEntry[][] => l['events'].toArray() as LogEventEntry[][]; @@ -130,7 +179,7 @@ describe('ClearcutLogger', () => { lifetimeGoogleAccounts: 9001, }); - const event = logger?.createLogEvent('abc', []); + const event = logger?.createLogEvent(EventNames.API_ERROR, []); expect(event?.event_metadata[0][0]).toEqual({ gemini_cli_key: EventMetadataKey.GEMINI_CLI_GOOGLE_ACCOUNTS_COUNT, @@ -138,26 +187,13 @@ describe('ClearcutLogger', () => { }); }); - it('logs the current surface from a github action', () => { - const { logger } = setup({}); - - vi.stubEnv('GITHUB_SHA', '8675309'); - - const event = logger?.createLogEvent('abc', []); - - expect(event?.event_metadata[0][1]).toEqual({ - gemini_cli_key: EventMetadataKey.GEMINI_CLI_SURFACE, - value: 'GitHub', - }); - }); - - it('honors the value from env.SURFACE over all others', () => { + it('logs the current surface', () => { const { logger } = setup({}); vi.stubEnv('TERM_PROGRAM', 'vscode'); vi.stubEnv('SURFACE', 'ide-1234'); - const event = logger?.createLogEvent('abc', []); + const event = logger?.createLogEvent(EventNames.API_ERROR, []); expect(event?.event_metadata[0][1]).toEqual({ gemini_cli_key: EventMetadataKey.GEMINI_CLI_SURFACE, @@ -209,7 +245,7 @@ describe('ClearcutLogger', () => { vi.stubEnv(key, value); } vi.stubEnv('TERM_PROGRAM', 'vscode'); - const event = logger?.createLogEvent('abc', []); + const event = logger?.createLogEvent(EventNames.API_ERROR, []); expect(event?.event_metadata[0][1]).toEqual({ gemini_cli_key: EventMetadataKey.GEMINI_CLI_SURFACE, value: expectedValue, @@ -218,10 +254,34 @@ describe('ClearcutLogger', () => { ); }); + describe('logChatCompressionEvent', () => { + it('logs an event with proper fields', () => { + const { logger } = setup(); + logger?.logChatCompressionEvent( + makeChatCompressionEvent({ + tokens_before: 9001, + tokens_after: 8000, + }), + ); + + const events = getEvents(logger!); + expect(events.length).toBe(1); + expect(events[0]).toHaveEventName(EventNames.CHAT_COMPRESSION); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_BEFORE, + '9001', + ]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_AFTER, + '8000', + ]); + }); + }); + describe('enqueueLogEvent', () => { it('should add events to the queue', () => { const { logger } = setup(); - logger!.enqueueLogEvent({ test: 'event1' }); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR)); expect(getEventsSize(logger!)).toBe(1); }); @@ -229,27 +289,43 @@ describe('ClearcutLogger', () => { const { logger } = setup(); for (let i = 0; i < TEST_ONLY.MAX_EVENTS; i++) { - logger!.enqueueLogEvent({ event_id: i }); + logger!.enqueueLogEvent( + logger!.createLogEvent(EventNames.API_ERROR, [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES, + value: `${i}`, + }, + ]), + ); } - expect(getEventsSize(logger!)).toBe(TEST_ONLY.MAX_EVENTS); - const firstEvent = JSON.parse( - getEvents(logger!)[0][0].source_extension_json, - ); - expect(firstEvent.event_id).toBe(0); + let events = getEvents(logger!); + expect(events.length).toBe(TEST_ONLY.MAX_EVENTS); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES, + '0', + ]); // This should push out the first event - logger!.enqueueLogEvent({ event_id: TEST_ONLY.MAX_EVENTS }); + logger!.enqueueLogEvent( + logger!.createLogEvent(EventNames.API_ERROR, [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES, + value: `${TEST_ONLY.MAX_EVENTS}`, + }, + ]), + ); + events = getEvents(logger!); + expect(events.length).toBe(TEST_ONLY.MAX_EVENTS); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES, + '1', + ]); - expect(getEventsSize(logger!)).toBe(TEST_ONLY.MAX_EVENTS); - const newFirstEvent = JSON.parse( - getEvents(logger!)[0][0].source_extension_json, - ); - expect(newFirstEvent.event_id).toBe(1); - const lastEvent = JSON.parse( - getEvents(logger!)[TEST_ONLY.MAX_EVENTS - 1][0].source_extension_json, - ); - expect(lastEvent.event_id).toBe(TEST_ONLY.MAX_EVENTS); + expect(events.at(TEST_ONLY.MAX_EVENTS - 1)).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES, + `${TEST_ONLY.MAX_EVENTS}`, + ]); }); }); @@ -261,7 +337,7 @@ describe('ClearcutLogger', () => { }, }); - logger!.enqueueLogEvent({ event_id: 1 }); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR)); const response = await logger!.flushToClearcut(); @@ -271,7 +347,7 @@ describe('ClearcutLogger', () => { it('should clear events on successful flush', async () => { const { logger } = setup(); - logger!.enqueueLogEvent({ event_id: 1 }); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR)); const response = await logger!.flushToClearcut(); expect(getEvents(logger!)).toEqual([]); @@ -282,8 +358,8 @@ describe('ClearcutLogger', () => { const { logger } = setup(); server.resetHandlers(http.post(CLEARCUT_URL, () => HttpResponse.error())); - logger!.enqueueLogEvent({ event_id: 1 }); - logger!.enqueueLogEvent({ event_id: 2 }); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_REQUEST)); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR)); expect(getEventsSize(logger!)).toBe(2); const x = logger!.flushToClearcut(); @@ -291,7 +367,9 @@ describe('ClearcutLogger', () => { expect(getEventsSize(logger!)).toBe(2); const events = getEvents(logger!); - expect(JSON.parse(events[0][0].source_extension_json).event_id).toBe(1); + + expect(events.length).toBe(2); + expect(events[0]).toHaveEventName(EventNames.API_REQUEST); }); it('should handle an HTTP error and requeue events', async () => { @@ -310,23 +388,22 @@ describe('ClearcutLogger', () => { ), ); - logger!.enqueueLogEvent({ event_id: 1 }); - logger!.enqueueLogEvent({ event_id: 2 }); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_REQUEST)); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR)); expect(getEvents(logger!).length).toBe(2); await logger!.flushToClearcut(); - expect(getEvents(logger!).length).toBe(2); const events = getEvents(logger!); - expect(JSON.parse(events[0][0].source_extension_json).event_id).toBe(1); + + expect(events[0]).toHaveEventName(EventNames.API_REQUEST); }); }); describe('requeueFailedEvents logic', () => { it('should limit the number of requeued events to max_retry_events', () => { const { logger } = setup(); - const maxRetryEvents = TEST_ONLY.MAX_RETRY_EVENTS; - const eventsToLogCount = maxRetryEvents + 5; + const eventsToLogCount = TEST_ONLY.MAX_RETRY_EVENTS + 5; const eventsToSend: LogEventEntry[][] = []; for (let i = 0; i < eventsToLogCount; i++) { eventsToSend.push([ @@ -339,13 +416,13 @@ describe('ClearcutLogger', () => { requeueFailedEvents(logger!, eventsToSend); - expect(getEventsSize(logger!)).toBe(maxRetryEvents); + expect(getEventsSize(logger!)).toBe(TEST_ONLY.MAX_RETRY_EVENTS); const firstRequeuedEvent = JSON.parse( getEvents(logger!)[0][0].source_extension_json, - ); + ) as { event_id: string }; // The last `maxRetryEvents` are kept. The oldest of those is at index `eventsToLogCount - maxRetryEvents`. expect(firstRequeuedEvent.event_id).toBe( - eventsToLogCount - maxRetryEvents, + eventsToLogCount - TEST_ONLY.MAX_RETRY_EVENTS, ); }); @@ -355,7 +432,7 @@ describe('ClearcutLogger', () => { const spaceToLeave = 5; const initialEventCount = maxEvents - spaceToLeave; for (let i = 0; i < initialEventCount; i++) { - logger!.enqueueLogEvent({ event_id: `initial_${i}` }); + logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR)); } expect(getEventsSize(logger!)).toBe(initialEventCount); @@ -382,7 +459,7 @@ describe('ClearcutLogger', () => { // The first element in the deque is the one with id 'failed_5'. const firstRequeuedEvent = JSON.parse( getEvents(logger!)[0][0].source_extension_json, - ); + ) as { event_id: string }; expect(firstRequeuedEvent.event_id).toBe('failed_5'); }); }); diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts index 200a1a0d..14551824 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts @@ -20,6 +20,7 @@ import { MalformedJsonResponseEvent, IdeConnectionEvent, KittySequenceOverflowEvent, + ChatCompressionEvent, } from '../types.js'; import { EventMetadataKey } from './event-metadata-key.js'; import { Config } from '../../config/config.js'; @@ -33,20 +34,23 @@ import { FixedDeque } from 'mnemonist'; import { GIT_COMMIT_INFO, CLI_VERSION } from '../../generated/git-commit.js'; import { DetectedIde, detectIde } from '../../ide/detect-ide.js'; -const start_session_event_name = 'start_session'; -const new_prompt_event_name = 'new_prompt'; -const tool_call_event_name = 'tool_call'; -const api_request_event_name = 'api_request'; -const api_response_event_name = 'api_response'; -const api_error_event_name = 'api_error'; -const end_session_event_name = 'end_session'; -const flash_fallback_event_name = 'flash_fallback'; -const loop_detected_event_name = 'loop_detected'; -const next_speaker_check_event_name = 'next_speaker_check'; -const slash_command_event_name = 'slash_command'; -const malformed_json_response_event_name = 'malformed_json_response'; -const ide_connection_event_name = 'ide_connection'; -const kitty_sequence_overflow_event_name = 'kitty_sequence_overflow'; +export enum EventNames { + START_SESSION = 'start_session', + NEW_PROMPT = 'new_prompt', + TOOL_CALL = 'tool_call', + API_REQUEST = 'api_request', + API_RESPONSE = 'api_response', + API_ERROR = 'api_error', + END_SESSION = 'end_session', + FLASH_FALLBACK = 'flash_fallback', + LOOP_DETECTED = 'loop_detected', + NEXT_SPEAKER_CHECK = 'next_speaker_check', + SLASH_COMMAND = 'slash_command', + MALFORMED_JSON_RESPONSE = 'malformed_json_response', + IDE_CONNECTION = 'ide_connection', + KITTY_SEQUENCE_OVERFLOW = 'kitty_sequence_overflow', + CHAT_COMPRESSION = 'chat_compression', +} export interface LogResponse { nextRequestWaitMs?: number; @@ -58,7 +62,7 @@ export interface LogEventEntry { } export interface EventValue { - gemini_cli_key: EventMetadataKey | string; + gemini_cli_key: EventMetadataKey; value: string; } @@ -168,7 +172,7 @@ export class ClearcutLogger { ClearcutLogger.instance = undefined; } - enqueueLogEvent(event: object): void { + enqueueLogEvent(event: LogEvent): void { try { // Manually handle overflow for FixedDeque, which throws when full. const wasAtCapacity = this.events.size >= MAX_EVENTS; @@ -196,7 +200,7 @@ export class ClearcutLogger { } } - createLogEvent(name: string, data: EventValue[]): LogEvent { + createLogEvent(eventName: EventNames, data: EventValue[] = []): LogEvent { const email = getCachedGoogleAccount(); data = addDefaultFields(data); @@ -204,7 +208,7 @@ export class ClearcutLogger { const logEvent: LogEvent = { console_type: 'GEMINI_CLI', application: 102, // GEMINI_CLI - event_name: name, + event_name: eventName as string, event_metadata: [data], }; @@ -386,7 +390,7 @@ export class ClearcutLogger { ]; // Flush start event immediately - this.enqueueLogEvent(this.createLogEvent(start_session_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.START_SESSION, data)); this.flushToClearcut().catch((error) => { console.debug('Error flushing to Clearcut:', error); }); @@ -412,7 +416,7 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(new_prompt_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.NEW_PROMPT, data)); this.flushIfNeeded(); } @@ -466,7 +470,7 @@ export class ClearcutLogger { } } - const logEvent = this.createLogEvent(tool_call_event_name, data); + const logEvent = this.createLogEvent(EventNames.TOOL_CALL, data); this.enqueueLogEvent(logEvent); this.flushIfNeeded(); } @@ -483,7 +487,7 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(api_request_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.API_REQUEST, data)); this.flushIfNeeded(); } @@ -540,7 +544,7 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(api_response_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.API_RESPONSE, data)); this.flushIfNeeded(); } @@ -572,10 +576,27 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(api_error_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.API_ERROR, data)); this.flushIfNeeded(); } + logChatCompressionEvent(event: ChatCompressionEvent): void { + const data: EventValue[] = [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_BEFORE, + value: `${event.tokens_before}`, + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_AFTER, + value: `${event.tokens_after}`, + }, + ]; + + this.enqueueLogEvent( + this.createLogEvent(EventNames.CHAT_COMPRESSION, data), + ); + } + logFlashFallbackEvent(event: FlashFallbackEvent): void { const data: EventValue[] = [ { @@ -588,7 +609,7 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(flash_fallback_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.FLASH_FALLBACK, data)); this.flushToClearcut().catch((error) => { console.debug('Error flushing to Clearcut:', error); }); @@ -606,7 +627,7 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(loop_detected_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.LOOP_DETECTED, data)); this.flushIfNeeded(); } @@ -631,7 +652,7 @@ export class ClearcutLogger { ]; this.enqueueLogEvent( - this.createLogEvent(next_speaker_check_event_name, data), + this.createLogEvent(EventNames.NEXT_SPEAKER_CHECK, data), ); this.flushIfNeeded(); } @@ -658,7 +679,7 @@ export class ClearcutLogger { }); } - this.enqueueLogEvent(this.createLogEvent(slash_command_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.SLASH_COMMAND, data)); this.flushIfNeeded(); } @@ -672,7 +693,7 @@ export class ClearcutLogger { ]; this.enqueueLogEvent( - this.createLogEvent(malformed_json_response_event_name, data), + this.createLogEvent(EventNames.MALFORMED_JSON_RESPONSE, data), ); this.flushIfNeeded(); } @@ -685,7 +706,7 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(ide_connection_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.IDE_CONNECTION, data)); this.flushIfNeeded(); } @@ -702,7 +723,7 @@ export class ClearcutLogger { ]; this.enqueueLogEvent( - this.createLogEvent(kitty_sequence_overflow_event_name, data), + this.createLogEvent(EventNames.KITTY_SEQUENCE_OVERFLOW, data), ); this.flushIfNeeded(); } @@ -716,7 +737,7 @@ export class ClearcutLogger { ]; // Flush immediately on session end. - this.enqueueLogEvent(this.createLogEvent(end_session_event_name, data)); + this.enqueueLogEvent(this.createLogEvent(EventNames.END_SESSION, data)); this.flushToClearcut().catch((error) => { console.debug('Error flushing to Clearcut:', error); }); diff --git a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts index 7ec0bccb..d9fa16a9 100644 --- a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts +++ b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts @@ -228,17 +228,10 @@ export enum EventMetadataKey { // Logs the length of the kitty sequence that overflowed. GEMINI_CLI_KITTY_SEQUENCE_LENGTH = 53, -} -export function getEventMetadataKey( - keyName: string, -): EventMetadataKey | undefined { - // Access the enum member by its string name - const key = EventMetadataKey[keyName as keyof typeof EventMetadataKey]; + // Logs the number of tokens before context window compression. + GEMINI_CLI_COMPRESSION_TOKENS_BEFORE = 60, - // Check if the result is a valid enum member (not undefined and is a number) - if (typeof key === 'number') { - return key; - } - return undefined; + // Logs the number of tokens after context window compression. + GEMINI_CLI_COMPRESSION_TOKENS_AFTER = 61, } diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index 7d840815..0d978fb2 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -16,7 +16,7 @@ export const EVENT_FLASH_FALLBACK = 'gemini_cli.flash_fallback'; export const EVENT_NEXT_SPEAKER_CHECK = 'gemini_cli.next_speaker_check'; export const EVENT_SLASH_COMMAND = 'gemini_cli.slash_command'; export const EVENT_IDE_CONNECTION = 'gemini_cli.ide_connection'; - +export const EVENT_CHAT_COMPRESSION = 'gemini_cli.chat_compression'; export const METRIC_TOOL_CALL_COUNT = 'gemini_cli.tool.call.count'; export const METRIC_TOOL_CALL_LATENCY = 'gemini_cli.tool.call.latency'; export const METRIC_API_REQUEST_COUNT = 'gemini_cli.api.request.count'; diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index 7775802d..b0c26046 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -28,6 +28,7 @@ export { logFlashFallback, logSlashCommand, logKittySequenceOverflow, + logChatCompression, } from './loggers.js'; export { StartSessionEvent, @@ -43,6 +44,8 @@ export { SlashCommandEvent, makeSlashCommandEvent, SlashCommandStatus, + ChatCompressionEvent, + makeChatCompressionEvent, } from './types.js'; export { SpanStatusCode, ValueType } from '@opentelemetry/api'; export { SemanticAttributes } from '@opentelemetry/semantic-conventions'; diff --git a/packages/core/src/telemetry/integration.test.circular.ts b/packages/core/src/telemetry/integration.test.circular.ts index 958ec3cb..acfb513e 100644 --- a/packages/core/src/telemetry/integration.test.circular.ts +++ b/packages/core/src/telemetry/integration.test.circular.ts @@ -56,7 +56,8 @@ describe('Circular Reference Integration Test', () => { const logger = ClearcutLogger.getInstance(mockConfig); expect(() => { - logger?.enqueueLogEvent(problematicEvent); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + logger?.enqueueLogEvent(problematicEvent as any); }).not.toThrow(); }); }); diff --git a/packages/core/src/telemetry/loggers.test.ts b/packages/core/src/telemetry/loggers.test.ts index e1c4e65b..a8c5ed88 100644 --- a/packages/core/src/telemetry/loggers.test.ts +++ b/packages/core/src/telemetry/loggers.test.ts @@ -34,6 +34,7 @@ import { logUserPrompt, logToolCall, logFlashFallback, + logChatCompression, } from './loggers.js'; import { ToolCallDecision } from './tool-call-decision.js'; import { @@ -43,12 +44,15 @@ import { ToolCallEvent, UserPromptEvent, FlashFallbackEvent, + makeChatCompressionEvent, } from './types.js'; import * as metrics from './metrics.js'; import * as sdk from './sdk.js'; import { vi, describe, beforeEach, it, expect } from 'vitest'; import { GenerateContentResponseUsageMetadata } from '@google/genai'; import * as uiTelemetry from './uiTelemetry.js'; +import { makeFakeConfig } from '../test-utils/config.js'; +import { ClearcutLogger } from './clearcut-logger/clearcut-logger.js'; describe('loggers', () => { const mockLogger = { @@ -68,6 +72,45 @@ describe('loggers', () => { vi.setSystemTime(new Date('2025-01-01T00:00:00.000Z')); }); + describe('logChatCompression', () => { + beforeEach(() => { + vi.spyOn(metrics, 'recordChatCompressionMetrics'); + vi.spyOn(ClearcutLogger.prototype, 'logChatCompressionEvent'); + }); + + it('logs the chat compression event to Clearcut', () => { + const mockConfig = makeFakeConfig(); + + const event = makeChatCompressionEvent({ + tokens_before: 9001, + tokens_after: 9000, + }); + + logChatCompression(mockConfig, event); + + expect( + ClearcutLogger.prototype.logChatCompressionEvent, + ).toHaveBeenCalledWith(event); + }); + + it('records the chat compression event to OTEL', () => { + const mockConfig = makeFakeConfig(); + + logChatCompression( + mockConfig, + makeChatCompressionEvent({ + tokens_before: 9001, + tokens_after: 9000, + }), + ); + + expect(metrics.recordChatCompressionMetrics).toHaveBeenCalledWith( + mockConfig, + { tokens_before: 9001, tokens_after: 9000 }, + ); + }); + }); + describe('logCliConfiguration', () => { it('should log the cli configuration', () => { const mockConfig = { diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index afc92807..bfa98b32 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -19,6 +19,7 @@ import { EVENT_NEXT_SPEAKER_CHECK, SERVICE_NAME, EVENT_SLASH_COMMAND, + EVENT_CHAT_COMPRESSION, } from './constants.js'; import { ApiErrorEvent, @@ -33,12 +34,14 @@ import { LoopDetectedEvent, SlashCommandEvent, KittySequenceOverflowEvent, + ChatCompressionEvent, } from './types.js'; import { recordApiErrorMetrics, recordTokenUsageMetrics, recordApiResponseMetrics, recordToolCallMetrics, + recordChatCompressionMetrics, } from './metrics.js'; import { isTelemetrySdkInitialized } from './sdk.js'; import { uiTelemetryService, UiEvent } from './uiTelemetry.js'; @@ -380,6 +383,31 @@ export function logIdeConnection( logger.emit(logRecord); } +export function logChatCompression( + config: Config, + event: ChatCompressionEvent, +): void { + ClearcutLogger.getInstance(config)?.logChatCompressionEvent(event); + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': EVENT_CHAT_COMPRESSION, + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `Chat compression (Saved ${event.tokens_before - event.tokens_after} tokens)`, + attributes, + }; + logger.emit(logRecord); + + recordChatCompressionMetrics(config, { + tokens_before: event.tokens_before, + tokens_after: event.tokens_after, + }); +} + export function logKittySequenceOverflow( config: Config, event: KittySequenceOverflowEvent, diff --git a/packages/core/src/telemetry/metrics.test.ts b/packages/core/src/telemetry/metrics.test.ts index 7b430884..84c069cf 100644 --- a/packages/core/src/telemetry/metrics.test.ts +++ b/packages/core/src/telemetry/metrics.test.ts @@ -14,6 +14,7 @@ import type { } from '@opentelemetry/api'; import { Config } from '../config/config.js'; import { FileOperation } from './metrics.js'; +import { makeFakeConfig } from '../test-utils/config.js'; const mockCounterAddFn: Mock< (value: number, attributes?: Attributes, context?: Context) => void @@ -28,18 +29,18 @@ const mockCreateHistogramFn: Mock< (name: string, options?: unknown) => Histogram > = vi.fn(); -const mockCounterInstance = { +const mockCounterInstance: Counter = { add: mockCounterAddFn, -} as unknown as Counter; +} as Partial as Counter; -const mockHistogramInstance = { +const mockHistogramInstance: Histogram = { record: mockHistogramRecordFn, -} as unknown as Histogram; +} as Partial as Histogram; -const mockMeterInstance = { +const mockMeterInstance: Meter = { createCounter: mockCreateCounterFn.mockReturnValue(mockCounterInstance), createHistogram: mockCreateHistogramFn.mockReturnValue(mockHistogramInstance), -} as unknown as Meter; +} as Partial as Meter; function originalOtelMockFactory() { return { @@ -49,15 +50,19 @@ function originalOtelMockFactory() { ValueType: { INT: 1, }, + diag: { + setLogger: vi.fn(), + }, }; } -vi.mock('@opentelemetry/api', originalOtelMockFactory); +vi.mock('@opentelemetry/api'); describe('Telemetry Metrics', () => { let initializeMetricsModule: typeof import('./metrics.js').initializeMetrics; let recordTokenUsageMetricsModule: typeof import('./metrics.js').recordTokenUsageMetrics; let recordFileOperationMetricModule: typeof import('./metrics.js').recordFileOperationMetric; + let recordChatCompressionMetricsModule: typeof import('./metrics.js').recordChatCompressionMetrics; beforeEach(async () => { vi.resetModules(); @@ -71,6 +76,8 @@ describe('Telemetry Metrics', () => { initializeMetricsModule = metricsJsModule.initializeMetrics; recordTokenUsageMetricsModule = metricsJsModule.recordTokenUsageMetrics; recordFileOperationMetricModule = metricsJsModule.recordFileOperationMetric; + recordChatCompressionMetricsModule = + metricsJsModule.recordChatCompressionMetrics; const otelApiModule = await import('@opentelemetry/api'); @@ -85,6 +92,35 @@ describe('Telemetry Metrics', () => { mockCreateHistogramFn.mockReturnValue(mockHistogramInstance); }); + describe('recordChatCompressionMetrics', () => { + it('does not record metrics if not initialized', () => { + const lol = makeFakeConfig({}); + + recordChatCompressionMetricsModule(lol, { + tokens_after: 100, + tokens_before: 200, + }); + + expect(mockCounterAddFn).not.toHaveBeenCalled(); + }); + + it('records token compression with the correct attributes', () => { + const config = makeFakeConfig({}); + initializeMetricsModule(config); + + recordChatCompressionMetricsModule(config, { + tokens_after: 100, + tokens_before: 200, + }); + + expect(mockCounterAddFn).toHaveBeenCalledWith(1, { + 'session.id': 'test-session-id', + tokens_after: 100, + tokens_before: 200, + }); + }); + }); + describe('recordTokenUsageMetrics', () => { const mockConfig = { getSessionId: () => 'test-session-id', diff --git a/packages/core/src/telemetry/metrics.ts b/packages/core/src/telemetry/metrics.ts index a0996410..c1125086 100644 --- a/packages/core/src/telemetry/metrics.ts +++ b/packages/core/src/telemetry/metrics.ts @@ -21,6 +21,7 @@ import { METRIC_TOKEN_USAGE, METRIC_SESSION_COUNT, METRIC_FILE_OPERATION_COUNT, + EVENT_CHAT_COMPRESSION, } from './constants.js'; import { Config } from '../config/config.js'; import { DiffStat } from '../tools/tools.js'; @@ -38,6 +39,7 @@ let apiRequestCounter: Counter | undefined; let apiRequestLatencyHistogram: Histogram | undefined; let tokenUsageCounter: Counter | undefined; let fileOperationCounter: Counter | undefined; +let chatCompressionCounter: Counter | undefined; let isMetricsInitialized = false; function getCommonAttributes(config: Config): Attributes { @@ -88,6 +90,10 @@ export function initializeMetrics(config: Config): void { description: 'Counts file operations (create, read, update).', valueType: ValueType.INT, }); + chatCompressionCounter = meter.createCounter(EVENT_CHAT_COMPRESSION, { + description: 'Counts chat compression events.', + valueType: ValueType.INT, + }); const sessionCounter = meter.createCounter(METRIC_SESSION_COUNT, { description: 'Count of CLI sessions started.', valueType: ValueType.INT, @@ -96,6 +102,17 @@ export function initializeMetrics(config: Config): void { isMetricsInitialized = true; } +export function recordChatCompressionMetrics( + config: Config, + args: { tokens_before: number; tokens_after: number }, +) { + if (!chatCompressionCounter || !isMetricsInitialized) return; + chatCompressionCounter.add(1, { + ...getCommonAttributes(config), + ...args, + }); +} + export function recordToolCallMetrics( config: Config, functionName: string, diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index 3fd16caf..d5dda177 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -14,7 +14,7 @@ import { ToolCallDecision, } from './tool-call-decision.js'; -interface BaseTelemetryEvent { +export interface BaseTelemetryEvent { 'event.name': string; /** Current timestamp in ISO 8601 format */ 'event.timestamp': string; @@ -292,7 +292,7 @@ export class NextSpeakerCheckEvent implements BaseTelemetryEvent { export interface SlashCommandEvent extends BaseTelemetryEvent { 'event.name': 'slash_command'; - 'event.timestamp': string; // ISO 8106 + 'event.timestamp': string; command: string; subcommand?: string; status?: SlashCommandStatus; @@ -317,6 +317,25 @@ export enum SlashCommandStatus { ERROR = 'error', } +export interface ChatCompressionEvent extends BaseTelemetryEvent { + 'event.name': 'chat_compression'; + 'event.timestamp': string; + tokens_before: number; + tokens_after: number; +} + +export function makeChatCompressionEvent({ + tokens_before, + tokens_after, +}: Omit): ChatCompressionEvent { + return { + 'event.name': 'chat_compression', + 'event.timestamp': new Date().toISOString(), + tokens_before, + tokens_after, + }; +} + export class MalformedJsonResponseEvent implements BaseTelemetryEvent { 'event.name': 'malformed_json_response'; 'event.timestamp': string;