Skip to content

Commit 8139a33

Browse files
rchiodorchiodo
authored
Add more telemetry around ipywidgets (#11034)
* Add more telemetry around ipywidgets * Fix linter * Add message hook count to telemetry * Exclude a directory from duplicate
1 parent 63fd864 commit 8139a33

File tree

23 files changed

+220
-52
lines changed

23 files changed

+220
-52
lines changed

‎.sonarcloud.properties

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
11
sonar.sources=src/client,src/datascience-ui
22
sonar.tests=src/test
33
sonar.cfamily.build-wrapper-output.bypass=true
4-
4+
sonar.cpd.exclusions=src/datascience-ui/**/redux/actions.ts

‎.vscode/launch.json

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,9 @@
2424
// Enable this to turn on redux logging during debugging
2525
"XVSC_PYTHON_FORCE_LOGGING": "1",
2626
// Enable this to try out new experiments locally
27-
"XVSC_PYTHON_LOAD_EXPERIMENTS_FROM_FILE" : "1"
27+
"XVSC_PYTHON_LOAD_EXPERIMENTS_FROM_FILE" : "1",
28+
// Enable this to log telemetry to the output during debugging
29+
"XVSC_PYTHON_LOG_TELEMETRY": "1"
2830
}
2931
},
3032
{

‎news/3 Code Health/11027.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
Add telemetry around ipywidgets usage, failures, and overhead.

‎src/client/datascience/constants.ts

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -289,8 +289,11 @@ export enum Telemetry {
289289
GatheredNotebookSaved = 'DATASCIENCE.GATHERED_NOTEBOOK_SAVED',
290290
GatherQualityReport = 'DS_INTERNAL.GATHER_QUALITY_REPORT',
291291
ZMQNotSupported = 'DATASCIENCE.ZMQ_NATIVE_BINARIES_NOT_LOADING',
292+
IPyWidgetLoadSuccess = 'DS_INTERNAL.IPYWIDGET_LOAD_SUCCESS',
292293
IPyWidgetLoadFailure = 'DS_INTERNAL.IPYWIDGET_LOAD_FAILURE',
293-
IPyWidgetLoadDisabled = 'DS_INTERNAL.IPYWIDGET_LOAD_DISABLED'
294+
IPyWidgetLoadDisabled = 'DS_INTERNAL.IPYWIDGET_LOAD_DISABLED',
295+
IPyWidgetOverhead = 'DS_INTERNAL.IPYWIDGET_OVERHEAD',
296+
IPyWidgetRenderFailure = 'DS_INTERNAL.IPYWIDGET_RENDER_FAILURE'
294297
}
295298

296299
export enum NativeKeyboardCommandTelemetry {

‎src/client/datascience/interactive-common/interactiveWindowTypes.ts

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,8 @@ import {
1010
CommonActionType,
1111
IAddCellAction,
1212
ILoadIPyWidgetClassFailureAction,
13-
LoadIPyWidgetClassDisabledAction
13+
LoadIPyWidgetClassDisabledAction,
14+
LoadIPyWidgetClassLoadAction
1415
} from '../../../datascience-ui/interactive-common/redux/reducers/types';
1516
import { PythonInterpreter } from '../../interpreter/contracts';
1617
import { LiveKernelModel } from '../jupyter/kernels/types';
@@ -108,8 +109,10 @@ export enum InteractiveWindowMessages {
108109
ReceivedUpdateModel = 'received_update_model',
109110
OpenSettings = 'open_settings',
110111
UpdateDisplayData = 'update_display_data',
112+
IPyWidgetLoadSuccess = 'ipywidget_load_success',
111113
IPyWidgetLoadFailure = 'ipywidget_load_failure',
112-
IPyWidgetLoadDisabled = 'ipywidget_load_disabled'
114+
IPyWidgetLoadDisabled = 'ipywidget_load_disabled',
115+
IPyWidgetRenderFailure = 'ipywidget_render_failure'
113116
}
114117

115118
export enum IPyWidgetMessages {
@@ -584,6 +587,8 @@ export class IInteractiveWindowMapping {
584587
public [SharedMessages.UpdateSettings]: string;
585588
public [SharedMessages.LocInit]: string;
586589
public [InteractiveWindowMessages.UpdateDisplayData]: KernelMessage.IUpdateDisplayDataMsg;
590+
public [InteractiveWindowMessages.IPyWidgetLoadSuccess]: LoadIPyWidgetClassLoadAction;
587591
public [InteractiveWindowMessages.IPyWidgetLoadFailure]: ILoadIPyWidgetClassFailureAction;
588592
public [InteractiveWindowMessages.IPyWidgetLoadDisabled]: LoadIPyWidgetClassDisabledAction;
593+
public [InteractiveWindowMessages.IPyWidgetRenderFailure]: Error;
589594
}

‎src/client/datascience/interactive-common/synchronization.ts

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -85,8 +85,10 @@ const messageWithMessageTypes: MessageMapping<IInteractiveWindowMapping> & Messa
8585
[CommonActionType.PostOutgoingMessage]: MessageType.other,
8686
[CommonActionType.REFRESH_VARIABLES]: MessageType.other,
8787
[CommonActionType.FOCUS_INPUT]: MessageType.other,
88+
[CommonActionType.LOAD_IPYWIDGET_CLASS_SUCCESS]: MessageType.other,
8889
[CommonActionType.LOAD_IPYWIDGET_CLASS_FAILURE]: MessageType.other,
8990
[CommonActionType.LOAD_IPYWIDGET_CLASS_DISABLED_FAILURE]: MessageType.other,
91+
[CommonActionType.IPYWIDGET_RENDER_FAILURE]: MessageType.other,
9092

9193
// Types from InteractiveWindowMessages
9294
[InteractiveWindowMessages.Activate]: MessageType.other,
@@ -112,8 +114,10 @@ const messageWithMessageTypes: MessageMapping<IInteractiveWindowMapping> & Messa
112114
[InteractiveWindowMessages.GotoCodeCell]: MessageType.syncWithLiveShare,
113115
[InteractiveWindowMessages.GotoCodeCell]: MessageType.syncWithLiveShare,
114116
[InteractiveWindowMessages.Interrupt]: MessageType.other,
117+
[InteractiveWindowMessages.IPyWidgetLoadSuccess]: MessageType.other,
115118
[InteractiveWindowMessages.IPyWidgetLoadFailure]: MessageType.other,
116119
[InteractiveWindowMessages.IPyWidgetLoadDisabled]: MessageType.other,
120+
[InteractiveWindowMessages.IPyWidgetRenderFailure]: MessageType.other,
117121
[InteractiveWindowMessages.LoadAllCells]: MessageType.other,
118122
[InteractiveWindowMessages.LoadAllCellsComplete]: MessageType.other,
119123
[InteractiveWindowMessages.LoadOnigasmAssemblyRequest]: MessageType.other,

‎src/client/datascience/ipywidgets/ipyWidgetMessageDispatcher.ts

Lines changed: 34 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -13,10 +13,17 @@ import { IDisposable } from '../../common/types';
1313
import { createDeferred, Deferred } from '../../common/utils/async';
1414
import { noop } from '../../common/utils/misc';
1515
import { deserializeDataViews, serializeDataViews } from '../../common/utils/serializers';
16+
import { sendTelemetryEvent } from '../../telemetry';
17+
import { Telemetry } from '../constants';
1618
import { IInteractiveWindowMapping, IPyWidgetMessages } from '../interactive-common/interactiveWindowTypes';
1719
import { INotebook, INotebookProvider, KernelSocketInformation } from '../types';
1820
import { IIPyWidgetMessageDispatcher, IPyWidgetMessage } from './types';
1921

22+
type PendingMessage = {
23+
resultPromise: Deferred<void>;
24+
startTime: number;
25+
};
26+
2027
// tslint:disable: no-any
2128
/**
2229
* This class maps between messages from the react code and talking to a real kernel.
@@ -42,7 +49,10 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
4249
private disposed = false;
4350
private pendingMessages: string[] = [];
4451
private subscribedToKernelSocket: boolean = false;
45-
private waitingMessageIds = new Map<string, Deferred<void>>();
52+
private waitingMessageIds = new Map<string, PendingMessage>();
53+
private totalWaitTime: number = 0;
54+
private totalWaitedMessages: number = 0;
55+
private hookCount: number = 0;
4656
constructor(private readonly notebookProvider: INotebookProvider, public readonly notebookIdentity: Uri) {
4757
// Always register this comm target.
4858
// Possible auto start is disabled, and when cell is executed with widget stuff, this comm target will not have
@@ -61,6 +71,8 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
6171
this.onKernelSocketMessage = this.onKernelSocketMessage.bind(this);
6272
}
6373
public dispose() {
74+
// Send overhead telemetry for our message hooking
75+
this.sendOverheadTelemetry();
6476
this.disposed = true;
6577
while (this.disposables.length) {
6678
const disposable = this.disposables.shift();
@@ -155,7 +167,7 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
155167
this.pendingMessages.shift();
156168
}
157169
this.sentKernelOptions = false;
158-
this.waitingMessageIds.forEach((d) => d.resolve());
170+
this.waitingMessageIds.forEach((d) => d.resultPromise.resolve());
159171
this.waitingMessageIds.clear();
160172
this.messageHookRequests.forEach((m) => m.resolve(false));
161173
this.messageHookRequests.clear();
@@ -195,11 +207,14 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
195207
// If this is shell control message, mirror to the other side. This is how
196208
// we get the kernel in the UI to have the same set of futures we have on this side
197209
if (typeof data === 'string') {
210+
const startTime = Date.now();
198211
// tslint:disable-next-line: no-require-imports
199212
const jupyterLabSerialize = require('@jupyterlab/services/lib/kernel/serialize') as typeof import('@jupyterlab/services/lib/kernel/serialize'); // NOSONAR
200213
const msg = jupyterLabSerialize.deserialize(data);
201214
if (msg.channel === 'shell' && msg.header.msg_type === 'execute_request') {
202215
await this.mirrorExecuteRequest(msg as KernelMessage.IExecuteRequestMsg); // NOSONAR
216+
this.totalWaitTime = Date.now() - startTime;
217+
this.totalWaitedMessages += 1;
203218
}
204219
}
205220
}
@@ -210,15 +225,15 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
210225

211226
private mirrorExecuteRequest(msg: KernelMessage.IExecuteRequestMsg) {
212227
const promise = createDeferred<void>();
213-
this.waitingMessageIds.set(msg.header.msg_id, promise);
228+
this.waitingMessageIds.set(msg.header.msg_id, { startTime: Date.now(), resultPromise: promise });
214229
this.raisePostMessage(IPyWidgetMessages.IPyWidgets_mirror_execute, { id: msg.header.msg_id, msg });
215230
return promise.promise;
216231
}
217232

218233
private onKernelSocketMessage(data: WebSocketData) {
219234
const msgUuid = uuid();
220235
const promise = createDeferred<void>();
221-
this.waitingMessageIds.set(msgUuid, promise);
236+
this.waitingMessageIds.set(msgUuid, { startTime: Date.now(), resultPromise: promise });
222237
if (typeof data === 'string') {
223238
this.raisePostMessage(IPyWidgetMessages.IPyWidgets_msg, { id: msgUuid, data });
224239
} else {
@@ -230,10 +245,12 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
230245
return promise.promise;
231246
}
232247
private onKernelSocketResponse(payload: { id: string }) {
233-
const promise = this.waitingMessageIds.get(payload.id);
234-
if (promise) {
248+
const pending = this.waitingMessageIds.get(payload.id);
249+
if (pending) {
235250
this.waitingMessageIds.delete(payload.id);
236-
promise.resolve();
251+
this.totalWaitTime += Date.now() - pending.startTime;
252+
this.totalWaitedMessages += 1;
253+
pending.resultPromise.resolve();
237254
}
238255
}
239256
private sendPendingMessages() {
@@ -302,6 +319,7 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
302319

303320
private registerMessageHook(msgId: string) {
304321
if (this.notebook && !this.messageHooks.has(msgId)) {
322+
this.hookCount += 1;
305323
const callback = this.messageHookCallback.bind(this);
306324
this.messageHooks.set(msgId, callback);
307325
this.notebook.registerMessageHook(msgId, callback);
@@ -357,4 +375,13 @@ export class IPyWidgetMessageDispatcher implements IIPyWidgetMessageDispatcher {
357375
promise.resolve(args.msgType.includes('comm') ? true : args.result);
358376
}
359377
}
378+
379+
private sendOverheadTelemetry() {
380+
sendTelemetryEvent(Telemetry.IPyWidgetOverhead, 0, {
381+
totalOverheadInMs: this.totalWaitTime,
382+
numberOfMessagesWaitedOn: this.totalWaitedMessages,
383+
averageWaitTime: this.totalWaitTime / this.totalWaitedMessages,
384+
numberOfRegisteredHooks: this.hookCount
385+
});
386+
}
360387
}

‎src/client/datascience/ipywidgets/ipywidgetHandler.ts

Lines changed: 32 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,8 @@ import { inject, injectable } from 'inversify';
77
import { Event, EventEmitter, Uri } from 'vscode';
88
import {
99
ILoadIPyWidgetClassFailureAction,
10-
LoadIPyWidgetClassDisabledAction
10+
LoadIPyWidgetClassDisabledAction,
11+
LoadIPyWidgetClassLoadAction
1112
} from '../../../datascience-ui/interactive-common/redux/reducers/types';
1213
import { EnableIPyWidgets } from '../../common/experimentGroups';
1314
import { traceError } from '../../common/logger';
@@ -66,20 +67,39 @@ export class IPyWidgetHandler implements IInteractiveWindowListener {
6667
public onMessage(message: string, payload?: any): void {
6768
if (message === InteractiveWindowMessages.NotebookIdentity) {
6869
this.saveIdentity(payload).catch((ex) => traceError('Failed to initialize ipywidgetHandler', ex));
70+
} else if (message === InteractiveWindowMessages.IPyWidgetLoadSuccess) {
71+
this.sendLoadSucceededTelemetry(payload);
6972
} else if (message === InteractiveWindowMessages.IPyWidgetLoadFailure) {
7073
this.sendLoadFailureTelemetry(payload);
7174
} else if (message === InteractiveWindowMessages.IPyWidgetLoadDisabled) {
7275
this.sendLoadDisabledTelemetry(payload);
76+
} else if (message === InteractiveWindowMessages.IPyWidgetRenderFailure) {
77+
this.sendRenderFailureTelemetry(payload);
7378
}
7479
// tslint:disable-next-line: no-any
7580
this.getIPyWidgetMessageDispatcher()?.receiveMessage({ message: message as any, payload }); // NOSONAR
7681
}
7782

83+
private hash(s: string): string {
84+
return this.hashFn().update(s).digest('hex');
85+
}
86+
87+
private sendLoadSucceededTelemetry(payload: LoadIPyWidgetClassLoadAction) {
88+
try {
89+
sendTelemetryEvent(Telemetry.IPyWidgetLoadSuccess, 0, {
90+
moduleHash: this.hash(payload.moduleName),
91+
moduleVersion: payload.moduleVersion
92+
});
93+
} catch {
94+
// do nothing on failure
95+
}
96+
}
97+
7898
private sendLoadFailureTelemetry(payload: ILoadIPyWidgetClassFailureAction) {
7999
try {
80100
sendTelemetryEvent(Telemetry.IPyWidgetLoadFailure, 0, {
81101
isOnline: payload.isOnline,
82-
moduleHash: this.hashFn(payload.moduleName),
102+
moduleHash: this.hash(payload.moduleName),
83103
moduleVersion: payload.moduleVersion
84104
});
85105
} catch {
@@ -89,13 +109,22 @@ export class IPyWidgetHandler implements IInteractiveWindowListener {
89109
private sendLoadDisabledTelemetry(payload: LoadIPyWidgetClassDisabledAction) {
90110
try {
91111
sendTelemetryEvent(Telemetry.IPyWidgetLoadDisabled, 0, {
92-
moduleHash: this.hashFn(payload.moduleName),
112+
moduleHash: this.hash(payload.moduleName),
93113
moduleVersion: payload.moduleVersion
94114
});
95115
} catch {
96116
// do nothing on failure
97117
}
98118
}
119+
120+
private sendRenderFailureTelemetry(payload: Error) {
121+
try {
122+
traceError('Error rendering a widget: ', payload);
123+
sendTelemetryEvent(Telemetry.IPyWidgetRenderFailure);
124+
} catch {
125+
// Do nothing on a failure
126+
}
127+
}
99128
private getIPyWidgetMessageDispatcher() {
100129
if (!this.notebookIdentity || !this.enabled) {
101130
return;

‎src/client/telemetry/index.ts

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1939,6 +1939,10 @@ export interface IEventNamePropertyMapping {
19391939
* Telemetry event sent when the ZMQ native binaries do not work.
19401940
*/
19411941
[Telemetry.ZMQNotSupported]: undefined | never;
1942+
/**
1943+
* Telemetry event sent when an ipywidget module loads. Module name is hashed.
1944+
*/
1945+
[Telemetry.IPyWidgetLoadSuccess]: { moduleHash: string; moduleVersion: string };
19421946
/**
19431947
* Telemetry event sent when an ipywidget module fails to load. Module name is hashed.
19441948
*/
@@ -1947,4 +1951,17 @@ export interface IEventNamePropertyMapping {
19471951
* Telemetry event sent when an loading of 3rd party ipywidget JS scripts from 3rd party source has been disabled.
19481952
*/
19491953
[Telemetry.IPyWidgetLoadDisabled]: { moduleHash: string; moduleVersion: string };
1954+
/**
1955+
* Telemetry event sent to indicate the overhead of syncing the kernel with the UI.
1956+
*/
1957+
[Telemetry.IPyWidgetOverhead]: {
1958+
totalOverheadInMs: number;
1959+
numberOfMessagesWaitedOn: number;
1960+
averageWaitTime: number;
1961+
numberOfRegisteredHooks: number;
1962+
};
1963+
/**
1964+
* Telemetry event sent when the widget render function fails (note, this may not be sufficient to capture all failures).
1965+
*/
1966+
[Telemetry.IPyWidgetRenderFailure]: never | undefined;
19501967
}

‎src/datascience-ui/history-react/interactiveCell.tsx

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -82,7 +82,8 @@ export class InteractiveCell extends React.Component<IInteractiveCellProps> {
8282

8383
private scrollAndFlash() {
8484
if (this.wrapperRef && this.wrapperRef.current) {
85-
if (this.wrapperRef.current.scrollIntoView) {
85+
// tslint:disable-next-line: no-any
86+
if ((this.wrapperRef.current as any).scrollIntoView) {
8687
this.wrapperRef.current.scrollIntoView({ behavior: 'auto', block: 'nearest', inline: 'nearest' });
8788
}
8889
this.wrapperRef.current.classList.add('flash');
@@ -104,7 +105,8 @@ export class InteractiveCell extends React.Component<IInteractiveCellProps> {
104105

105106
// Scroll into view (since we have focus). However this function
106107
// is not supported on enzyme
107-
if (this.wrapperRef.current.scrollIntoView) {
108+
// tslint:disable-next-line: no-any
109+
if ((this.wrapperRef.current as any).scrollIntoView) {
108110
this.wrapperRef.current.scrollIntoView({ behavior: 'auto', block: 'nearest', inline: 'nearest' });
109111
}
110112
}
@@ -156,6 +158,7 @@ export class InteractiveCell extends React.Component<IInteractiveCellProps> {
156158
maxTextSize={this.props.maxTextSize}
157159
themeMatplotlibPlots={themeMatplotlibPlots}
158160
loadWidgetScriptsFromThirdPartySource={loadWidgetScriptsFromThirdPartySource}
161+
widgetFailed={this.props.widgetFailed}
159162
/>
160163
</div>
161164
</div>
@@ -221,10 +224,8 @@ export class InteractiveCell extends React.Component<IInteractiveCellProps> {
221224

222225
private onMouseClick = (ev: React.MouseEvent<HTMLDivElement>) => {
223226
// When we receive a click, propagate upwards. Might change our state
224-
if (this.props.clickCell) {
225-
ev.stopPropagation();
226-
this.props.clickCell(this.props.cellVM.cell.id);
227-
}
227+
ev.stopPropagation();
228+
this.props.clickCell(this.props.cellVM.cell.id);
228229
};
229230

230231
private renderControls = () => {

‎src/datascience-ui/history-react/redux/actions.ts

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -99,5 +99,7 @@ export const actionCreators = {
9999
sortAscending: true,
100100
startIndex,
101101
pageSize
102-
})
102+
}),
103+
widgetFailed: (ex: Error): CommonAction<Error> =>
104+
createIncomingActionWithPayload(CommonActionType.IPYWIDGET_RENDER_FAILURE, ex)
103105
};

‎src/datascience-ui/history-react/redux/reducers/index.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,8 +39,10 @@ export const reducerMap: Partial<IInteractiveActionMapping> = {
3939
[CommonActionType.UNFOCUS_CELL]: Effects.unfocusCell,
4040
[CommonActionType.UNMOUNT]: Creation.unmount,
4141
[CommonActionType.FOCUS_INPUT]: CommonEffects.focusInput,
42+
[CommonActionType.LOAD_IPYWIDGET_CLASS_SUCCESS]: CommonEffects.handleLoadIPyWidgetClassSuccess,
4243
[CommonActionType.LOAD_IPYWIDGET_CLASS_FAILURE]: CommonEffects.handleLoadIPyWidgetClassFailure,
4344
[CommonActionType.LOAD_IPYWIDGET_CLASS_DISABLED_FAILURE]: CommonEffects.handleLoadIPyWidgetClassDisabled,
45+
[CommonActionType.IPYWIDGET_RENDER_FAILURE]: CommonEffects.handleIPyWidgetRenderFailure,
4446

4547
// Messages from the webview (some are ignored)
4648
[InteractiveWindowMessages.Undo]: Execution.undo,

‎src/datascience-ui/interactive-common/cellOutput.tsx

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@ interface ICellOutputProps {
3636
hideOutput?: boolean;
3737
themeMatplotlibPlots?: boolean;
3838
expandImage(imageHtml: string): void;
39+
widgetFailed(ex: Error): void;
3940
}
4041

4142
interface ICellOutputData {
@@ -592,6 +593,10 @@ export class CellOutput extends React.Component<ICellOutputProps> {
592593
private async createWidgetView(widgetData: nbformat.IMimeBundle & { model_id: string; version_major: number }) {
593594
const wm = await this.getWidgetManager();
594595
const element = this.ipyWidgetRef.current!;
595-
return wm?.renderWidget(widgetData, element);
596+
try {
597+
return await wm?.renderWidget(widgetData, element);
598+
} catch (ex) {
599+
this.props.widgetFailed(ex);
600+
}
596601
}
597602
}

0 commit comments

Comments
 (0)