Showing output channel via API steals editor focus, output channel output is delayed

[ArtemGovorov]

• VSCode Version: Version 1.28.0-insider (1.28.0-insider) 2558a72
• OS Version: macOS 10.13.3

Steps to Reproduce:

1. Create a simple extension with the following code:

  const outputChannel = window.createOutputChannel(`My Test`);
  outputChannel.append('Test');
  outputChannel.show();

  setTimeout(() => {
    outputChannel.show();
  }, 5000);

2. Run the extension and observe:

• a significant delay (~2 seconds) between displaying the output channel and displaying its content (that is appended at the same time);
• focus stealing by the output channel after closing the channel and showing it after 5 seconds.

Here's the GIF to demonstrate the issue in 1.28.0-insider:

Here's the GIF to demonstrate that it's working as expected in 1.27.2:

Does this issue occur when all extensions are disabled?: Yes

[vscodebot]

(Experimental duplicate detection)
Thanks for submitting this issue. Please also check if it is already covered by an existing one, like:

• Allow extensions to create file based output channel (#41672)
• Creating multiple output channels by the same name results in an inability to select all but the last one (#49186)
• Add isVisible to OutputChannel (#57410)
• Use spdlog for output channels straight from the extension host (#57618)
• Allow folding in output channels (#36609)

[sandy081]

@ArtemGovorov

a significant delay (~2 seconds) between displaying the output channel and displaying its content (that is appended at the same time);

This delay is introduced in insiders and it helps to reduce CPU load on the UI process. Output channels are mainly meant to be used as log views (like git, typescript) and are not required to show the content immediately.

At the same time we also provided a flag if you want to enforce immediate updates but this comes at the cost of higher CPU usage. Please see https://github.com/Microsoft/vscode/blob/master/src/vs/vscode.d.ts#L6241

focus stealing by the output channel after closing the channel and showing it after 5 seconds.

This is happening because you are calling show API and not saying to preserve the focus. It has an optional flag preserveFocus that will allow you to control the focus. This exists from the beginning but it is not working as expected before. Fixed it so that when you pass preserveFocus flag to true, focus is preserved otherwise panel gets focused.

[sandy081]

To verify:

When you pass preserveFocus flag to true in show api, focus is preserved otherwise panel gets focused.

[sandy081]

@ArtemGovorov

At the same time we also provided a flag if you want to enforce immediate updates but this comes at the cost of higher CPU usage. Please see /src/vs/vscode.d.ts@master#L6241

We decided not to provide this flag and all output channels behave the same.

[sandy081]

Some Context: Output channels on Extension Host writes appended data into a log file with an interval of 500ms. UI process updates the channel UI by listening to the log file changes at regular interval of 500ms. So an appended message can appear in the UI in not less than 1s.

Small improvement: channel.show() now flushes the appended content so that the UI gets updated sooner.

But delay can be still noticed among the appended messages due to the flushing interval in Extension Host and listening interval in UI.

[sandy081]

Output channel looks like following with an extension sample similar to that in description

 const outputChannel = vscode.window.createOutputChannel(`My Test`);
    outputChannel.appendLine('Test');
    outputChannel.show(true);

    setTimeout(() => {
        outputChannel.appendLine('Test1');
        outputChannel.appendLine('Test2');
        outputChannel.appendLine('Test3');
    }, 5000);

[ArtemGovorov]

@sandy081 @jrieken

We decided not to provide this flag and all output channels behave the same.

Why not? Unfortunately, the new behaviour is a huge drawback for our extensions. The flag was the only way to preserve the existing behaviour and without the flag it is a very painful breaking change for us and our users.

To provide some context, our extension is used by many thousands of VS Code users every day (~2.2 million downloads) and it allows to log values in real-time. We are constantly optimising our engine to reduce the time of getting the live feedback back to user, we are trying to squeeze out every millisecond we can.

So far for many versions of VS Code it had been working like this:

and now (without the flag) it will look something like this:

So what felt like an almost instant feedback, now feels very sluggish and significantly affects the UX.

The same applies to our other extension called Wallaby.js and its tests output. We are providing real-time feedback from running tests, so every millisecond counts, and now the output is going to be affected by the 500ms delay.

While we do understand the motivation behind changing the default behaviour, could you please re-consider providing a way to switch back to what had been working for a long time prior to the change?

[sandy081]

@ArtemGovorov I see how the delay is affecting your use case. I am adding another improvement to reduce the time lapse between the time data is appended and it is shown in the UI. If the data is appended to a visible channel, I would flush the data into the log (temp) file immediately and signal the UI about the change. UI fetches the data from the file and shows it. Here is the gif of the same example of yours with the above approach

I cannot say it is same as before, but it is fast enough and I think it is the best compromise to be efficient and faster.

[ArtemGovorov]

@sandy081 Thanks, it sounds like a great solution, and also no need to change the API! We will check it out.