Window freeze when receiving lots of output (renderer)

[StefH]

• VSCode Version: 1.5.2
• OS Version: Windows 2008R2

Steps to Reproduce:

1. Open an Java Maven project with a lot of tests
2. Do a maven clean install as task command

You get an error message like:

When you wait until Maven is finished running all the tests, the VS Code windows are completely blocked.

Is there a way to increase the time-out from the OUTPUTwindow?

[chrmarti]

Couldn't reproduce with a long-running task with lots of output on both OSX and Windows 10. It looks like the large amount of output did slow things down though. The fact that the task runs for a long time shouldn't cause any of this.

@StefH Could you paste your tasks.json for comparison? Thanks.

[StefH]

tasks.json

{
    // See https://go.microsoft.com/fwlink/?LinkId=733558
    // for the documentation about the tasks.json format
    "version": "0.1.0",
    "command": "mvn",
    "isShellCommand": true,
    "showOutput": "always",
    "suppressTaskName": true,
    "tasks": [
        {
            "taskName": "clean"
        },
        {
            "taskName": "compile",
            "args": [
                "clean",
                "install"
            ],
            "isBuildCommand": true
        },
        {
            "taskName": "test"
        },
        {
            "taskName": "package"
        },
        {
            "taskName": "verify"
        }
    ]
}

[chrmarti]

Related to #7353

[dbaeumer]

This is actually a problem of the output window. Moving to @isidorn.

[dbaeumer]

I saw the same behavior last week when enabling typescript server tracing which writes a lot of output. In this setup no tasks are involved.

[isidorn]

September to investigate

[isidorn]

@dbaeumer can you please share your reproducable steps since I do not want to setup java in order to investigate this. How to setup typescript server tracing and how to get that huge amount of output? Thanks!

[dbaeumer]

Settings:

{
    "typescript.tsserver.trace": "verbose"
}

Open content assist quite frequently in a project that has a browser environment.

[bpasero]

I am not convinced that this is an issue with the output panel. I rather believe this is an issue with the extension host pumping data to the renderer and then getting stuck. I have test cases that produce the freeze when run from an extension and no freeze when run within the workbench:

Freeze from Extension (simple hello world extension with hello world command):

'use strict';

import * as vscode from 'vscode';

export function activate(context: vscode.ExtensionContext) {
    let disposable = vscode.commands.registerCommand('extension.sayHello', () => {
        vscode.window.showInformationMessage('Crashing!');
        const outputChannel = vscode.window.createOutputChannel("Test");
        outputChannel.show();
        lotsOfOutput(outputChannel);
    });

    context.subscriptions.push(disposable);
}

var max = 10000;
var i = 0;
function lotsOfOutput(outputChannel) {
    setTimeout(() => {
        outputChannel.appendLine(`[Trace - 9:21:49 AM] Sending request: quickinfo (89). Response expected: yes. Current queue length: 0
Arguments: {
    "file": "c:\\Users\\bpasero\\Desktop\\test-ts\\src\\extension.ts",
    "line": 8,
    "offset": 17
}`);
    i++;
    if (i < max)
        lotsOfOutput(outputChannel);
    }, 1);
}

No Freeze within Workbench (for testing purposes change the CloseEditorAction in actions.ts (vs\workbench\electron-browser\actions.ts) and invoke it:

export class CloseEditorAction extends Action {

    public static ID = 'workbench.action.closeActiveEditor';
    public static LABEL = nls.localize('closeActiveEditor', "Close Editor");

    constructor(
        id: string,
        label: string,
        @IOutputService private outputService: IOutputService,
        @IWorkbenchEditorService private editorService: IWorkbenchEditorService
    ) {
        super(id, label);
    }

    public run(): TPromise<any> {
        const channel = this.outputService.getChannel("foo");
        channel.show();

        lotsOfOutput(channel);

        return TPromise.as(false);
    }

    private appendOutput(channel): void {

    }
}


var max = 10000;
var i = 0;
function lotsOfOutput(outputChannel) {
    setTimeout(() => {
        outputChannel.append(`[Trace - 9:21:49 AM] Sending request: quickinfo (89). Response expected: yes. Current queue length: 0
Arguments: {
    "file": "c:\\Users\\bpasero\\Desktop\\test-ts\\src\\extension.ts",
    "line": 8,
    "offset": 17
}`);
    i++;
    if (i < max)
        lotsOfOutput(outputChannel);
    }, 1);
}

Adding @jrieken to the thread. I wonder if the direct call to append is too aggressive and needs some buffering.

[jrieken]

@bpasero @dbaeumer Things are being mixed up here. The initial bug talks about task.json which doesn't go via the extension host. Somehow you now brought the extension host into the game which is different.

[jrieken]

Also - if many messages are being send, a warning should be printed

[bpasero]

@jrieken yup, @dbaeumer filed a similar issue and I merged it here. see #12265 (comment)

Bottom line is that the TS extension can produce lots of output when the tracing option is turned on and this output is being send from the extension host.

[jrieken]

It actually does

[bpasero]

Btw I am on Windows 10 and see this, did not try on Mac. I am also scrolling in the output when this happens. The process monitor shows no activity when this happens, so it is not stuck in high CPU or high memory.

[jrieken]

45% of the time is spend in the OutputService, 17% in the OutputEditor, 7% GC'ing

CPU-20160929T100930.cpuprofile.zip

[jrieken]

So, I don't believe this is an issue specific to the extension host (albeit some more buffering could happen) but I see that most work is being spend in the parts outlined above.

[bpasero]

@jrieken can you reproduce the freeze? is this profile from running from extension host or main side?

[bpasero]

Also I am not convinced this issue can be tracked down by profiling: When VSCode freezes, there is no high CPU activity nor memory pressure.

[jrieken]

@bpasero It is very slow and 'yes' this is the main side (OutputService, string-utils etc).

[dbaeumer]

@StefH reported this when executing a task which is executed in the render (no extension host involved).

@bpasero may be an easy way to reproduce this is to write a node program that simply produces lots of output and start it via a task.

[bpasero]

Ok lets keep this item to look into the performance on the renderer side and #6737 to check for the extension side.

[bpasero]

I am seeing half of the time spend in the editor in setValue and about 15% in the append function of the outputService:

[bpasero]

For October to investigate if we can make this faster when lots of output is received. Moving since it is not a regression from previous milestones.

[bpasero]

@isidorn leaving to you if there is something we can improve. otherwise, the hang in the renderer is a different issue unrelated to consuming the output (related: #13736 and #13667)

[isidorn]

@bpasero looked in the output and there is nothing obvious to improve. AFAIK the slowness comes from nodejs/node#7657 as you pointed out in a different issue.
Thus closing this