add telemetry updates for openfile (#6257)

* copy ClientCollection.ts

* copy extension.ts

* copy client.ts

* rename LS message

* create new file

* spath to path

* remove uri with logged telemtery

* fix linter errors

* fix linter errors 2

* fix linter error 3

* change warm start collection

* nit

* bring setDidOpenTime to the beginnign of didOpen

* reply to reviews

Author: Elaheh Rashedi

Extension/src/LanguageServer/client.ts

@@ -161,6 +161,8 @@ function publishDiagnostics(params: PublishDiagnosticsParams): void {
 
     const realUri: vscode.Uri = vscode.Uri.parse(params.uri);
     diagnosticsCollection.set(realUri, diagnostics);
+
+    clientCollection.timeTelemetryCollector.setUpdateRangeTime(realUri);
 }
 
 interface WorkspaceFolderParams {
@@ -424,6 +426,10 @@ enum SemanticTokenModifiers {
     local = (1 << 2)
 }
 
+interface IntelliSenseSetup {
+    uri: string;
+}
+
 // Requests
 const QueryCompilerDefaultsRequest: RequestType<QueryCompilerDefaultsParams, configs.CompilerDefaults, void, void> = new RequestType<QueryCompilerDefaultsParams, configs.CompilerDefaults, void, void>('cpptools/queryCompilerDefaults');
 const QueryTranslationUnitSourceRequest: RequestType<QueryTranslationUnitSourceParams, QueryTranslationUnitSourceResult, void, void> = new RequestType<QueryTranslationUnitSourceParams, QueryTranslationUnitSourceResult, void, void>('cpptools/queryTranslationUnitSource');
@@ -482,6 +488,7 @@ const ShowMessageWindowNotification: NotificationType<ShowMessageWindowParams, v
 const ShowWarningNotification: NotificationType<ShowWarningParams, void> = new NotificationType<ShowWarningParams, void>('cpptools/showWarning');
 const ReportTextDocumentLanguage: NotificationType<string, void> = new NotificationType<string, void>('cpptools/reportTextDocumentLanguage');
 const SemanticTokensChanged: NotificationType<string, void> = new NotificationType<string, void>('cpptools/semanticTokensChanged');
+const IntelliSenseSetupNotification:  NotificationType<IntelliSenseSetup, void> = new NotificationType<IntelliSenseSetup, void>('cpptools/IntelliSenseSetup');
 
 let failureMessageShown: boolean = false;
 
@@ -1892,6 +1899,7 @@ export class DefaultClient implements Client {
         this.languageClient.onNotification(ShowWarningNotification, showWarning);
         this.languageClient.onNotification(ReportTextDocumentLanguage, (e) => this.setTextDocumentLanguage(e));
         this.languageClient.onNotification(SemanticTokensChanged, (e) => this.semanticTokensProvider?.invalidateFile(e));
+        this.languageClient.onNotification(IntelliSenseSetupNotification, (e) => this.logIntellisenseSetupTime(e));
         setupOutputHandlers();
     }
 
@@ -2154,6 +2162,10 @@ export class DefaultClient implements Client {
         }
     }
 
+    public logIntellisenseSetupTime(notification: IntelliSenseSetup): void {
+        clientCollection.timeTelemetryCollector.setSetupTime(vscode.Uri.parse(notification.uri));
+    }
+
     private promptCompileCommands(params: CompileCommandsPaths): void {
         if (!params.workspaceFolderUri) {
             return;

Extension/src/LanguageServer/clientCollection.ts

@@ -6,9 +6,10 @@
 
 import * as vscode from 'vscode';
 import * as util from '../common';
-import * as telemetry from '../telemetry';
 import * as cpptools from './client';
+import * as telemetry from '../telemetry';
 import { getCustomConfigProviders } from './customProviders';
+import { TimeTelemetryCollector } from './timeTelemetryCollector';
 
 const defaultClientKey: string = "@@default@@";
 export interface ClientKey {
@@ -22,6 +23,7 @@ export class ClientCollection {
     private defaultClient: cpptools.Client;
     private activeClient: cpptools.Client;
     private activeDocument?: vscode.TextDocument;
+    public timeTelemetryCollector: TimeTelemetryCollector;
 
     public get ActiveClient(): cpptools.Client { return this.activeClient; }
     public get Names(): ClientKey[] {
@@ -60,6 +62,8 @@ export class ClientCollection {
 
         this.disposables.push(vscode.workspace.onDidChangeWorkspaceFolders(e => this.onDidChangeWorkspaceFolders(e)));
         this.disposables.push(vscode.workspace.onDidCloseTextDocument(d => this.onDidCloseTextDocument(d)));
+
+        this.timeTelemetryCollector = new TimeTelemetryCollector();
     }
 
     public activeDocumentChanged(document: vscode.TextDocument): void {

Extension/src/LanguageServer/extension.ts

@@ -284,6 +284,12 @@ function realActivation(): void {
     clients = new ClientCollection();
     ui = getUI();
 
+    // Log cold start.
+    const activeEditor: vscode.TextEditor | undefined = vscode.window.activeTextEditor;
+    if (activeEditor) {
+        clients.timeTelemetryCollector.setFirstFile(activeEditor.document.uri);
+    }
+
     // There may have already been registered CustomConfigurationProviders.
     // Request for configurations from those providers.
     clients.forEach(client => {
@@ -405,6 +411,8 @@ function onDidChangeTextEditorSelection(event: vscode.TextEditorSelectionChangeE
 export function processDelayedDidOpen(document: vscode.TextDocument): void {
     const client: Client = clients.getClientFor(document.uri);
     if (client) {
+        // Log warm start.
+        clients.timeTelemetryCollector.setDidOpenTime(document.uri);
         if (clients.checkOwnership(client, document)) {
             if (!client.TrackedDocuments.has(document)) {
                 // If not yet tracked, process as a newly opened file.  (didOpen is sent to server in client.takeOwnership()).
@@ -1161,6 +1169,7 @@ function handleCrashFileRead(err: NodeJS.ErrnoException | undefined | null, data
 }
 
 export function deactivate(): Thenable<void> {
+    clients.timeTelemetryCollector.clear();
     console.log("deactivating extension");
     telemetry.logLanguageServerEvent("LanguageServerShutdown");
     clearInterval(intervalTimer);

Extension/src/LanguageServer/protocolFilter.ts

@@ -26,6 +26,8 @@ export function createProtocolFilter(clients: ClientCollection): Middleware {
         didOpen: (document, sendMessage) => {
             const editor: vscode.TextEditor | undefined = vscode.window.visibleTextEditors.find(e => e.document === document);
             if (editor) {
+                // Log warm start.
+                clients.timeTelemetryCollector.setDidOpenTime(document.uri);
                 // If the file was visible editor when we were activated, we will not get a call to
                 // onDidChangeVisibleTextEditors, so immediately open any file that is visible when we receive didOpen.
                 // Otherwise, we defer opening the file until it's actually visible.

Extension/src/LanguageServer/timeTelemetryCollector.ts

@@ -0,0 +1,84 @@
+/* --------------------------------------------------------------------------------------------
+ * Copyright (c) Microsoft Corporation. All Rights Reserved.
+ * See 'LICENSE' in the project root for license information.
+ * ------------------------------------------------------------------------------------------ */
+import * as telemetry from '../telemetry';
+import * as util from '../common';
+import * as vscode from 'vscode';
+
+interface TimeStampSequence {
+    firstFile?: number; // when the extension is activated by realActivation. Defined only for "cold" start cases.
+    didOpen: number; // when the file appears in the editor. Defined for "warm" start cases.
+    setup: number; // when the Intellisense_client constructor is completed
+    updateRange: number; // when publishDiagnostics & provideSemanticTokens is completed
+}
+
+export class TimeTelemetryCollector {
+
+    private cachedTimeStamps: Map<string, any> = new Map<string, any>(); // a map of uri's string to TimeStampSequence
+
+    public setFirstFile(uri: vscode.Uri): void {
+        if (util.fileIsCOrCppSource(uri.path)) {
+            const curTimeStamps: TimeStampSequence = this.getTimeStamp(uri.path);
+            curTimeStamps.firstFile = new Date().getTime();
+            this.cachedTimeStamps.set(uri.path, curTimeStamps);
+        }
+    }
+
+    public setDidOpenTime(uri: vscode.Uri): void {
+        const curTimeStamps: TimeStampSequence = this.getTimeStamp(uri.path);
+        curTimeStamps.didOpen = new Date().getTime();
+        this.cachedTimeStamps.set(uri.path, curTimeStamps);
+    }
+
+    public setSetupTime(uri: vscode.Uri): void {
+        const curTimeStamps: TimeStampSequence = this.getTimeStamp(uri.path);
+        curTimeStamps.setup = new Date().getTime();
+        this.cachedTimeStamps.set(uri.path, curTimeStamps);
+        if (curTimeStamps.didOpen && curTimeStamps.updateRange) {
+            this.logTelemetry(uri.path, curTimeStamps);
+        }
+    }
+
+    public setUpdateRangeTime(uri: vscode.Uri): void {
+        const curTimeStamps: TimeStampSequence = this.getTimeStamp(uri.path);
+        if (!curTimeStamps.updateRange) {
+            curTimeStamps.updateRange = new Date().getTime();
+            this.cachedTimeStamps.set(uri.path, curTimeStamps);
+        }
+        if (curTimeStamps.didOpen && curTimeStamps.setup) {
+            this.logTelemetry(uri.path, curTimeStamps);
+        }
+    }
+
+    public clear(): void {
+        console.log("clearing timestamp log");
+        this.cachedTimeStamps.clear();
+    }
+
+    private getTimeStamp(uri: string): TimeStampSequence {
+        return this.cachedTimeStamps.get(uri) ? this.cachedTimeStamps.get(uri) :
+            { firstFile: 0, didOpen: 0, setup: 0, updateRange: 0 };
+    }
+
+    private removeTimeStamp(uri: string): void {
+        this.cachedTimeStamps.delete(uri);
+    }
+
+    private logTelemetry(uri: string, timeStamps: TimeStampSequence): void {
+        const startTime: number = timeStamps.firstFile ? timeStamps.firstFile : timeStamps.didOpen;
+        let properties: any = {};
+        let metrics: any = {
+            "setupTime": (timeStamps.setup - startTime),
+            "updateRangeTime": (timeStamps.updateRange - timeStamps.setup),
+            "totalTime": (timeStamps.updateRange - startTime)
+        };
+        if (timeStamps.firstFile) {
+            properties = { "coldstart": "true" };
+            metrics = { "activationTime": (timeStamps.didOpen - startTime), ...metrics };
+        }
+        telemetry.logLanguageServerEvent("timeStamps", properties, metrics);
+
+        this.removeTimeStamp(uri);
+    }
+}