Performance of vscode.workspace.fs.readDirectory(Uri) is worse by *100 compared to vscode

[idantr]

Bug Description:

Update the description after comments by @vince-fugnitto :
When calling to vscode.workspace.fs.readFile(Uri) the amount of time it takes differ significally from the times of the same code in vscode:
Running the our code in vscode locally we get response times of ~15 ms

When running the code in Theia via electron locally n ~597ms range on the same file

** also we saw that in vscode that consecutive calls are even faster

Steps to Reproduce:

1. Create a very simple vscode plugin using the following code:

import * as vscode from 'vscode';
import * as _ from 'lodash';
import { promises as fs } from 'fs';
import * as path from 'path';
 
export async function activate(context: vscode.ExtensionContext) {
    context.subscriptions.push(vscode.commands.registerCommand('idan-test.readDirs', async () => {
        const baseUri: vscode.Uri = _.get(vscode.workspace.workspaceFolders, "[0].uri");
        const plUri: vscode.Uri = vscode.Uri.file(path.join(baseUri.fsPath, "package-lock.json"));
 
        const before = Date.now();
        const contentVscode: Uint8Array = await vscode.workspace.fs.readFile(plUri);
        const after = Date.now();
        vscode.window.showInformationMessage(`Result VSCODE - ${after - before}`);
        
        const beforeNode = Date.now();
        const contentNode = await fs.readFile(path.resolve(plUri.fsPath));
        const afterNode = Date.now();
        vscode.window.showInformationMessage(`Result NODE - ${afterNode - beforeNode}`);
    }));
}

2. in you projects folder insert the following file
   package-lock.json.txt
   (remove the ".txt" in the end)
   package-lock.json 486k

Additional Information

• Operating System: WIN10
• vscode 1.56.0
• theia latest master code revision 583220b

[vince-fugnitto]

When running the our code in vscode locally we get response times of ~4-10 ms to get 4 directories and a few files
When running the code in Theia in gitpod using Theia as the UI we are getting response times in ~400ms range to query the same project

@idantr we aren't really comparing similar things or under similar circumstances.

We are comparing vscode locally versus theia in the cloud (through gitpod with likely a server which is far away and will affect the response time due to the roundtrip). It would be better to get measurements of a similar use-case, perhaps vscode and theia locally (through electron) if we want to say it is "worse by 100* compared to vscode".

[vince-fugnitto]

Possibly related: #8242 (comment).

[paul-marechal]

When running the code in Theia in gitpod using Theia as the UI we are getting response times in ~400ms range to query the same project

Please try to trace this to know precisely where the time is spent as it could be due to various factors, like network.

[idantr]

After running the same in theia local browser vs. vscode the response times are the same
When running the same api vs. prallel node api i got response times of one factor better in node
example theia: 10ms to read 9-11 dirs
node: took 1ms

[idantr]

After testing I saw the same behavior in clean vscode. i will open an issue to vscode, closing this issue

[idantr]

@vince-fugnitto i updated the initial description.
i now tested theia running with electorn vs. vscode, both running locally and there is a significant reduction is performance in theia.
we get it in several filesystem api's we tested , (readDirectory readFile)

The difference between theia and vscode is the main issue,
** running same equivalent api directly using node "fs" was even faster.
can this be improved somehow?

[paul-marechal]

can this be improved somehow?

PRs are welcome at the moment.

[idantr]

@vince-fugnitto @paul-marechal
We did some more debugging and found that most of the time is spent in the RPC calls from frontend to the backend and back
those 2 calls on every request take most of the time.
Can we optimize the call from the plugin host to use node 'fs' directly when we identify that the uri is a real file system?
how would you suggest to continue? create a new dedicated provider for it?

[paul-marechal]

I don't know how this system works well enough, so I am not sure what the main approach should be.

From what I understand, you are saying that there are useless round trips happening? It makes sense to me that if we can avoid going to the frontend and back for no good reason then we should avoid it. Feel free to prototype something, I cannot dig deep enough to help you right now.

[idantr]

this issue is critical for us as our stakeholder are using theia extensively and we would like that they use vscode public api's and not custom code just for performance reasons.
@paul-marechal should this issue be raised in next the theia dev meeting? or would you recommend that to start a poc?

[paul-marechal]

@eclipse-theia/plugin-system anyone aware of this issue or has pointers for @idantr?

[tsmaeder]

@idantr You mentioned that the time is spent doing remote calls, is this wall clock time or do you you have any more detailed data on where in the code the time is spent?

Do you have an idea which messages are sent over the wire? In particular, are the contents of the file being streamed (onFileStreamData) or sent as a single message?

[idantr]

@tsmaeder yes we did measurements in strategic places in the code when running on electron locally
these are the results in ms i printed:
root INFO ******** time readFile for disk-file-system-provider.ts = 3 -> link
root INFO ******** time for $readFile in file-system-main-impl.ts = 232 -> link
root INFO [hosted-plugin: 45460] ******** time for readFile in file-system-ext-impl.ts = 533 link

so the call to fs.readFile is quick and is performed in the backend
to get the this call and back takes most of the time (remote calls same time for forward and same for back).
readFileStream was not called anywhere in the local flow.

in our implementation of theia i saw 2 singular websocket calls, one for each direction.

[paul-marechal]

file-system-main-impl.ts is running in the browser runtime, knowing that extensions are running on the backend this means the API goes backend to frontend and back... But since you tested on Electron we still serialize those calls over RPC, it seems surprising for it to take that long when everything's local.

What you measured paints an interesting picture, but it's still not clear what is causing this or where exactly the time is spent...

[tsmaeder]

@idantr thanks for the analysis, this is useful data. @paul-marechal I would be surprised if this was related to the data transfer time over the wire: As I understand it, we're talking about small text files (< 10kb). Over a 10mb/s line, that would take 10ms to transfer. So I'm not surprised that over the wire is +/- the same as electron. My money is on JSON.stringify(), but that's just a hunch.
@idantr while you have the measurement infrastructure in place: does it make a difference if you transfer large files vs. small files?

[slavik-lvovsky]

These are the required measurements:

1k file - 13-18 ms
5k file - 20-30 ms
62k file - 90-110 ms
477k file - 470-490 ms

[tsmaeder]

That looks pretty much linear with file size or slightly decreasing

[tsmaeder]

A quick inspection has revealed numerous areas for improvement:

1. Back end services are invoked through vscode-jsonrpc, which uses JSON.stringify() to encode messages. VS Code has it's own message protocol, which does not json-encode raw buffers.
2. For plugins, we run our own RpcProtocol implementation on top of the back end service protocol, which means we're encoding the same message twice
3. JSON.stringify() seems to grow linearly with the size of the encoded object, so at least it's O(n), like any sending of messages would be.
4. The size of the content response message in our services is about 3 times the size of the file we're reading: using json-encoded number arrays is very inefficient. A 1.43mb file results in an around 4.3 mb response message.

The lowest hanging fruit would probably be to encode the byte arrays for the file content more smartly. However, I believe in the long run we'll have to throw out the vscode-jsonrpc package and use our own implementation to have more control message serialisation.

[tsmaeder]

I've recently refactored RPCProtocol to be independent of plugin concerns, so I believe it could now be a base for replacing vscode-jsonrpc.

[tsmaeder]

t.b.h, I don't think this is an issue with JSON.stringify() or JSON.parse(): experimenting with those calls yields much smaller run times:

interface Foo {
    foo: number[];
}


let obj: Foo = {
    foo: []
}

for (let i= 0; i < 500000; i++) {
    obj.foo.push(i);
}

let start = new Date();
let stringed = JSON.stringify(obj);
stringed = JSON.stringify(stringed);

let copy = JSON.parse(stringed);
copy = JSON.parse(stringed);

let end= new Date();

console.info(end.getTime()-start.getTime());

finishes in 30 milliseconds.

[slavik-lvovsky]

If JSON.stringify does not cause the performance degradation, what could be a reason for the issue?

[tsmaeder]

@slavik-lvovsky your guess is as good as mine at this point in time; investigation is needed.

[tsmaeder]

An obvious (although not trivial) improvement we could make is this: when we hook up services from plugins to the browser, we forward the messages something like this in the back end (pseudocode):

connectionFromPluginHost.readFullMessage().then((message) {
   connectionToBrowser.send(message);
})

So we're always waiting to fully read the message from the plugin until we forward it to the browser (and vice-versa as well). This means that forwarding a message will roughly take double the time it takes to send a message over a single hop.
Alternatively, we could just stream the messages to the browser side instead: read a small bit of data and immediately send it to the browser. That way the time would be x+delta instead of 2x. For small messages it doesn't make a difference, but for large ones, it does.

[tsmaeder]

Especially with file system calls (which go from plugin-host to back-end to browser and back to the back end and optionally to a plugin), we could save quite some time on large messages.
Absent a streaming message router, using that streaming file read API might help in this case. We're not using it at this time, I believe)

[tsmaeder]

I did a very simple test reading 500kbytes from a raw nodejs websocket on localhost: reading 500k took 13ms. This seems consistent with the numbers VS Code is getting. So the performance hit really is in the communication layers we add on top of websocket. Here's the client code:

    let t0;

    const ws = new WebSocket('ws://localhost:9898/');

    ws.onopen = function () {
        console.log('WebSocket Client Connected');
        t0 = performance.now();
        ws.send('Hi this is web client.');
    };

    ws.onmessage = function (e) {
        const t1 = performance.now();
        console.log(`request took ${t1 - t0} milliseconds.`);

        console.log("Received: '" + e.data.length /1000 + " kbytes'");
    };

and here's the server:

wsServer.on('request', function(request) {
    const connection = request.accept(undefined, request.origin);

    connection.on('message', function(message) {
      console.log('Received Message:', message.utf8Data);
      connection.sendUTF(msg);
    });
    connection.on('close', function(reasonCode, description) {
        console.log('Client has disconnected.');
    });
});

[ChayaLau]

@tsmaeder - we are experiencing a general performance issues in all of the file system actions.
we are trying to figure out if the slowness when expanding a folder in the file explorer is related to this issue.

[tsmaeder]

@ChayaLau I can't really say, because I did not analyze that scenario. However, if we make message sending generally faster, every remote call should profit.
I would recommend that you instrument the corresponding call in both the DiskFileSystemProvider in the back end and the RemoteFileSystemProvider in the front end. If you get a lot of difference for the same operations, message sending is a contributing factor. But there might be other reasons, for example doing unnecessary work or bad caching strategies.

[tsmaeder]

I jotted down an attempt at a write-through RPC framework here: https://github.com/tsmaeder/message-rpc I call it the "nochebuena" code drop :-)

[tsmaeder]

I can read a file from disk via a pass-through channel in ~3ms, which is basically the time it takes to read from disk. If we put this together with the experiment above writing through a web socket, I think this is promising.