New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Now we report the times of the different tasks that happen until we launch and show the user page #301

Merged
merged 14 commits into from Mar 10, 2018

Conversation

Projects
None yet
2 participants
@digeff
Copy link
Contributor

digeff commented Mar 7, 2018

Now we report the times of the different tasks that happen until we launch and show the user page

@@ -57,11 +58,14 @@ suite('ChromeDebugAdapter', () => {
mockChromeConnection
.setup(x => x.attach(It.isValue(undefined), It.isValue(ATTACH_FAIL_PORT), It.isValue(undefined), It.isValue(undefined)))
.returns(() => utils.errP('Testing attach failed'));
mockChromeConnection
mockChromeConnection

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Fix indentation

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

Changed

.setup(x => x.isAttached)
.returns(() => false);
mockChromeConnection
.setup(x => x.onClose(It.isAny()));
mockChromeConnection
.setup(x => x.Events)
.returns(() => new StepProgressEventsEmitter);

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Missing ()?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

Changed

@@ -152,11 +153,15 @@ export abstract class ChromeDebugAdapter implements IDebugAdapter {

private _batchTelemetryReporter: BatchTelemetryReporter;

public constructor({ chromeConnection, lineColTransformer, sourceMapTransformer, pathTransformer, targetFilter, enableSourceMapCaching }: IChromeDebugAdapterOpts, session: ChromeDebugSession) {
public readonly Events: StepProgressEventsEmitter;

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Why capital E?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

I think I was thinking in C#... I'll change it to lowercase...

@@ -0,0 +1,139 @@
import { HighResTimer, calculateElapsedTime } from "./utils";

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Copyright header on new file

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

And single quotes

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

changed

milestoneName: string;
}

export interface ObservableEvents<T> { // Normally T will be an EventEmitter

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Then you can say T extends EventEmitter

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

Changed

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

Sorry, that was an older version of the code. Now T is just an interface, so we cannot make it extend EventEmitter. I changed this for:
// T is an interface that declares the on methods (listeners) that we can subscribe to

}
}

/* Use to track the time executing each step during launch

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Is this usage comment necessary? It's incomplete since it doesn't say how to create Events or a reporter, and things like this quickly get out of date. Since this already includes code that uses these objects, I'm not sure this is needed.

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

I removed the usage, and I left the sample telemetry

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

That will get out of date too. Is it helpful?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

I think it's helpful to have a reference to what kind of telemetry we expect. If you don't like having this in the code, I can move this to a OneNote or something

This comment has been minimized.

@roblourens

roblourens Mar 8, 2018

Member

I think it's just noise in the code.

This comment has been minimized.

@digeff

digeff Mar 10, 2018

Contributor

Removed

@@ -131,6 +140,8 @@ export class ChromeDebugSession extends LoggingDebugSession {
reportFailure(e);
}
this.failedRequest(request.command, response, e);
} finally {
this.Events.emitStepStarted(`WaitingAfter.ClientRequest.${request.command}`);

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Would it make more sense to emit that a step is complete, and have the emitter create the WaitingAfter events?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

I think that conceptually it does make more sense to emit when a step is completed.

In practice, some steps end sometimes in different locations due to multiple return statements or other strategies, and most steps usually begin in a single place, so it seemed simpler to track step beginnings rather than steps ends...

Ideally we should track both being and end with something like recordStep(() = doStepHere());. But that requires a much bigger code change, so I think that the simpler approach is better at this time. What do you think?

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

I think that this line is basically tracking the step end, so I was just suggesting that this line do something more like this.Events.emitStepComplete() and the emitter can turn that into a "WaitingAfter" step internally if it wants to.

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Or, the emitter can fire some event that says the step is complete, and the reporter could write that out as a WaitingAfter step if it wants to. Would that be more natural? If not you can ignore this feedback.

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

Sorry, I completely missed your point.

I like the idea of the method. I don't think that the behavior we have here for emitStepComplete would makes sense for all steps.
What do you think of using: this.Events.emitClientRequestCompleted(request.command) for this?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

After some more thinking, I think that this.events.emitStepCompleted(ClientRequest.${request.command}); makes the most sense... Changing to that...

This comment has been minimized.

@digeff

digeff Mar 8, 2018

Contributor

Sorry, I forgot to give you the full context.
We are only going to be tracking these steps while launching the browser. After the browser is launched, and we navigate to the user page, we "turn off" this logic/telemetry, and we don't record any more data...
We only care about setBreakpoints as part of the launch process (e.g. The configurationDone message won't be sent until we finish processing the setBreakpoints request). After we finish launching this operation will be a no-op.

This comment has been minimized.

@roblourens

roblourens Mar 8, 2018

Member

How does it get turned off? It looks like you build the report on shutdown() so it would collect data over the whole lifetime of the debug adapter.

And still, why wouldn't setBreakpoints be measured with the existing telemetry?

This comment has been minimized.

@digeff

digeff Mar 8, 2018

Contributor

I'm sorry, I should've sent the two PRs at the same time to give you the full context.
This PR works in conjunction with: Microsoft/vscode-chrome-debug#610
That is where we turn it off, etc...

This comment has been minimized.

@roblourens

roblourens Mar 9, 2018

Member

I still don't see how it's turned off in chrome-debug. Also I don't think it makes sense to start logging from -core and only turn it off from the subclass. Then it will log forever for anything besides chrome-debug that doesn't reach up and turn it off.

If this is all for chrome-debug, does any of it make sense for node-debug or any other consumers? If not, we need to rethink this approach.

I also still don't understand why the telemetry that times each request isn't sufficient for the part of this that measures requests. It's the right model for this sort of thing. setBreakpoints, and setExceptionBreakpoints won't come necessarily come one at a time as steps. They could overlap, and then I think your timings would be confusing.

ClientRequest.initialize [1.261372] // Time we spent processing the initialize request
WaitingAfter.ClientRequest.initialize [74.939561] // Time we spent after processing the initialize request for the client to send us another request
ClientRequest.launch [2.748096] // Time we spent processing the first part of the launch request until we actually start launching the target debugee .exe
LaunchTarget.LaunchExe 10.276666 // The time it takes to spawn the the target debugee .exe (We launch the .exe but we don't wait for it)

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Why are some arrays and some not?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

I forgot to update that comment.
"All" and milestones are single values. All the steps are now arrays.

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Why are they arrays?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

Some steps like Attach.RequestDebuggerTargetsInformation or setBreakpoints can happen multiple times. If that happens we send [, ]. For simplicity we assume that all "steps" can have multiple ocurrences

private reporter = new ExecutionTimingsReporter();
private haveLaunchExecutionTimingsBeenReported = false;

public static readonly NavigatedToUserRequestedUrlEventName = 'navigatedToUserRequestedUrl';

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Where is this fired from? And it's not clear that we need interfaces for every event that will be fired.

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

This will get fired from onFrameNavigated in vscode-chrome-debug.

This comment has been minimized.

@roblourens

roblourens Mar 9, 2018

Member

I don't think it should be referenced from here then. Navigating is a chrome-debug-specific concept, not something that -core needs to know about.

this.emit(stepStartedEventName, { stepName: stepName } as StepStartedEventArguments);
}

public emitMilestoneReached(milestoneName: string): void {

This comment has been minimized.

@roblourens

roblourens Mar 7, 2018

Member

Is this used anywhere?

This comment has been minimized.

@digeff

digeff Mar 7, 2018

Contributor

This will be used in configurationDone in vscode-chrome-debug

@digeff digeff force-pushed the digeff:launch_timings_telemetry_master branch from 772535b to 81e7204 Mar 10, 2018

digeff added some commits Mar 10, 2018

@@ -138,12 +148,23 @@ export class ChromeDebugSession extends LoggingDebugSession {
// { command: request.command, type: request.type };
private async reportTelemetry(eventName: string, propertiesSpecificToAction: {[property: string]: string}, action: (reportFailure: (failure: any) => void) => Promise<void>): Promise<void> {
const startProcessingTime = process.hrtime();
const startTime = Date.now();
const isSequentialRequest = eventName === "clientRequest/initialize" || eventName === "clientRequest/launch";

This comment has been minimized.

@roblourens

roblourens Mar 10, 2018

Member

attach?

This comment has been minimized.

@digeff

digeff Mar 10, 2018

Contributor

changed

@@ -314,7 +319,8 @@ export abstract class ChromeDebugAdapter implements IDebugAdapter {
}
*/
telemetry.reportEvent('debugStarted', { request: 'attach', args: Object.keys(args) });
return this.doAttach(args.port, args.url, args.address, args.timeout, args.websocketUrl, args.extraCRDPChannelPort);
await this.doAttach(args.port, args.url, args.address, args.timeout, args.websocketUrl, args.extraCRDPChannelPort);
this.events.emitMilestoneReached(ChromeDebugSession.FinishedStartingUpEventName);

This comment has been minimized.

@roblourens

roblourens Mar 10, 2018

Member

I guess for launch this will be called from chrome-debug. For consistency, let's remove this and emit this from chrome-debug too.

This comment has been minimized.

@digeff

digeff Mar 10, 2018

Contributor

Changed

digeff added some commits Mar 10, 2018

@roblourens roblourens merged commit a24315e into Microsoft:master Mar 10, 2018

3 checks passed

continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
license/cla All CLA requirements met.
Details

@digeff digeff deleted the digeff:launch_timings_telemetry_master branch Mar 10, 2018

@roblourens roblourens added this to the March 2018 milestone Apr 3, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment