Skip to content
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.

Sign up for GitHub

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

chore: log js stacks from unresponsive window #241390

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
+59 −3
Open

chore: log js stacks from unresponsive window #241390

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions src/main.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -286,6 +286,12 @@ function configureCommandlineSwitchesSync(cliArgs: NativeParsedArgs) {
}
});

// Following features are enabled from the runtime:
// `DocumentPolicyIncludeJSCallStacksInCrashReports` - https://www.electronjs.org/docs/latest/api/web-frame-main#framecollectjavascriptcallstack-experimental
const featuresToEnable =
`DocumentPolicyIncludeJSCallStacksInCrashReports, ${app.commandLine.getSwitchValue('enable-features')}`;
app.commandLine.appendSwitch('enable-features', featuresToEnable);

// Following features are disabled from the runtime:
// `CalculateNativeWinOcclusion` - Disable native window occlusion tracker (https://groups.google.com/a/chromium.org/g/embedder-dev/c/ZF3uHHyWLKw/m/VDN2hDXMAAAJ)
// `PlzDedicatedWorker` - Refs https://github.com/microsoft/vscode/issues/233060#issuecomment-2523212427
Expand Down
6 changes: 5 additions & 1 deletion src/vs/base/common/network.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -358,7 +358,11 @@ class FileAccessImpl {
export const FileAccess = new FileAccessImpl();

export const CacheControlheaders: Record<string, string> = Object.freeze({
'Cache-Control': 'no-cache, no-store',
'Cache-Control': 'no-cache, no-store'
});

export const DocumentPolicyheaders: Record<string, string> = Object.freeze({
'Document-Policy': 'include-js-call-stacks-in-crash-reports'
});

export namespace COI {
Expand Down
12 changes: 11 additions & 1 deletion src/vs/platform/protocol/electron-main/protocolMainService.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@

import { session } from 'electron';
import { Disposable, IDisposable, toDisposable } from '../../../base/common/lifecycle.js';
import { COI, FileAccess, Schemas, CacheControlheaders } from '../../../base/common/network.js';
import { COI, FileAccess, Schemas, CacheControlheaders, DocumentPolicyheaders } from '../../../base/common/network.js';
import { basename, extname, normalize } from '../../../base/common/path.js';
import { isLinux } from '../../../base/common/platform.js';
import { TernarySearchTree } from '../../../base/common/ternarySearchTree.js';
Expand Down Expand Up @@ -113,6 +113,16 @@ export class ProtocolMainService extends Disposable implements IProtocolMainServ
};
}

// Document-policy header is needed for collecting
// JavaScript callstacks via https://www.electronjs.org/docs/latest/api/web-frame-main#framecollectjavascriptcallstack-experimental
// until https://github.com/electron/electron/issues/45356 is resolved.
if (extname(path).toLowerCase() === '.html') {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be using the same code as above for COI.CoopAndCope?

headers = {
...headers,
...DocumentPolicyheaders
};
}

// first check by validRoots
if (this.validRoots.findSubstr(path)) {
return callback({ path, headers });
Expand Down
7 changes: 6 additions & 1 deletion src/vs/platform/window/electron-main/window.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -196,5 +196,10 @@ export const enum WindowError {
/**
* Maps to the `did-fail-load` event on a `WebContents`.
*/
LOAD = 3
LOAD = 3,

/**
* Maps to the `responsive` event on a `BrowserWindow`.
*/
RESPONSIVE = 4,
}
31 changes: 31 additions & 0 deletions src/vs/platform/windows/electron-main/windowImpl.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -540,6 +540,8 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
private pendingLoadConfig: INativeWindowConfiguration | undefined;
private wasLoaded = false;

private JScallStackCollector: NodeJS.Timeout | undefined;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💄 : Class members first letter are lowercase unless maybe its a static constant.


constructor(
config: IWindowCreationOptions,
@ILogService logService: ILogService,
Expand Down Expand Up @@ -653,6 +655,7 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {

// Window error conditions to handle
this._register(Event.fromNodeEventEmitter(this._win, 'unresponsive')(() => this.onWindowError(WindowError.UNRESPONSIVE)));
this._register(Event.fromNodeEventEmitter(this._win, 'responsive')(() => this.onWindowError(WindowError.RESPONSIVE)));
this._register(Event.fromNodeEventEmitter(this._win.webContents, 'render-process-gone', (event, details) => details)(details => this.onWindowError(WindowError.PROCESS_GONE, { ...details })));
this._register(Event.fromNodeEventEmitter(this._win.webContents, 'did-fail-load', (event, exitCode, reason) => ({ exitCode, reason }))(({ exitCode, reason }) => this.onWindowError(WindowError.LOAD, { reason, exitCode })));

Expand Down Expand Up @@ -728,6 +731,7 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
}

private async onWindowError(error: WindowError.UNRESPONSIVE): Promise<void>;
private async onWindowError(error: WindowError.RESPONSIVE): Promise<void>;
private async onWindowError(error: WindowError.PROCESS_GONE, details: { reason: string; exitCode: number }): Promise<void>;
private async onWindowError(error: WindowError.LOAD, details: { reason: string; exitCode: number }): Promise<void>;
private async onWindowError(type: WindowError, details?: { reason?: string; exitCode?: number }): Promise<void> {
Expand All @@ -739,6 +743,9 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
case WindowError.UNRESPONSIVE:
this.logService.error('CodeWindow: detected unresponsive');
break;
case WindowError.RESPONSIVE:
this.logService.error('CodeWindow: recovered from unresponsive');
break;
case WindowError.LOAD:
this.logService.error(`CodeWindow: failed to load (reason: ${details?.reason || '<unknown>'}, code: ${details?.exitCode || '<unknown>'})`);
break;
Expand Down Expand Up @@ -797,6 +804,9 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
return;
}

// Interrupt V8 and collect JavaScript stack
this.startCollectingJScallStacks();

// Show Dialog
const { response, checkboxChecked } = await this.dialogMainService.showMessageBox({
type: 'warning',
Expand All @@ -813,6 +823,7 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
// Handle choice
if (response !== 2 /* keep waiting */) {
const reopen = response === 0;
this.stopCollectingJScallStacks();
await this.destroyWindow(reopen, checkboxChecked);
}
}
Expand Down Expand Up @@ -845,6 +856,9 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
await this.destroyWindow(reopen, checkboxChecked);
}
break;
case WindowError.RESPONSIVE:
this.stopCollectingJScallStacks();
break;
}
}

Expand Down Expand Up @@ -958,6 +972,23 @@ export class CodeWindow extends BaseWindow implements ICodeWindow {
}
}

private async startCollectingJScallStacks(): Promise<void> {
if (this.JScallStackCollector) {
return;
}
this.JScallStackCollector = setInterval(async () => {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We have a RunOnceScheduler utility for this that is a bit easier to work with.

const stack = await this._win.webContents.mainFrame.collectJavaScriptCallStack();
this.logService.error('CodeWindow unresponsive : ', stack);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we remember the last printed stack and simply ignore it when it always repeats?

}, 1000);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this stop at one point printing? What if the user leaves this running? Maybe the interval is also quite short and do we know that the stack would be any different after collecting it once?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So we stop printing in 2 cases currently,

  1. Once the user has responded to the dialog with close or reopen
  2. If window becomes responsive again, that is signaled by the responsive event from the runtime.

I am thinking of the following scenarios of unresponsive windows,

  1. A long running JS task that will eventually recover, the unresponsive event can happen in this case if the main thread is blocked for more than the period that the main process thinks is ideal to respond to user inputs.
  2. An infinite loop that will never recover, it could be async stack that re-enters from a different stack.

The call stack api basically interrupts V8 at a point in time and collects the current executing stack, since it is a single sample it would be hard to reason either of those cases. Hence I am thinking of collecting samples at an interval till the stop printing cases kick in. The interval I chose was just the defaults for most sampling profilers. But what I don't is aggregate the stacks so it would indeed make the console noisy.

Should we remember the last printed stack and simply ignore it when it always repeats?

Instead of ignoring, what if we aggregate a count for each repetitive stacks and only display the result at the end of the stack collection period. Something like

[main 2025-02-20T20:07:19.499Z] CodeWindow: detected unresponsive
[main 2025-02-20T20:07:20.366Z] CodeWindow unresponsive sample <N> times:  
 <M>   at NativeAuxiliaryWindowService.createContainer (vscode-file://vscode-app/Users/demohan/github/vscode/out/vs/workbench/services/auxiliaryWindow/electron-sandbox/auxiliaryWindowService.js:118:9)
 <M>   at NativeAuxiliaryWindowService.open (vscode-file://vscode-app/Users/demohan/github/vscode/out/vs/workbench/services/auxiliaryWindow/browser/auxiliaryWindowService.js:181:50)

where N = Unresponsive time end - Unresponsive time start / Sample interval
where M = Number of times the stack appeared in the N period

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would just stop after 10 iterations or so, reducing the risk of filling the log forever.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you clarify the situation where the unresponsive interval will never end ? My understanding is that we always prompt a dialog and user has to choose an action to close or reopen at some point. Also my new suggestion is to print the log only once at the end of the unresponsive session.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of ignoring, what if we aggregate a count for each repetitive stacks and only display the result at the end of the stack collection period.

+1 on that. I would not print as you capture but aggregate (by count and maybe timestamp) so that you can print a summary. Either when responsive again, confirmed, or after a long'ish freeze time (in case never recovers). With that don't flood the log and have trace-like information

}

private async stopCollectingJScallStacks(): Promise<void> {
if (this.JScallStackCollector) {
clearInterval(this.JScallStackCollector);
this.JScallStackCollector = undefined;
}
}

addTabbedWindow(window: ICodeWindow): void {
if (isMacintosh && window.win) {
this._win.addTabbedWindow(window.win);
Expand Down
Loading