Query-Solid
Query-Solid copied to clipboard
LDflex
Browser performance issue on iterative property access
I face performances issues when accessing datas on a container. It makes all our apps not useable for now with LDFlex. For example, with the following code:
await solid.data.context.extend(base_context)
const container = solid.data["https://apiprod.happy-dev.fr/clients/"];
console.time(container.toString())
for await (const r of container.ldp_contains) {
console.time(r.toString())
console.log((await r.img).toString());
console.timeEnd(r.toString())
}
console.timeEnd(container.toString())
It takes ~3000ms to display 70 times the img property of a resource.
For each resource, it takes between 10ms to 90ms to display its img.
Is there something we can do to improve this?
3s is long indeed. However, are we sure it is an LDflex problem? Because the above involves (independently of whether you are using LDflex or not) fetching 70 resources over HTTP. I suspect those are the source of the 10–90ms delay.
A solution would be to parallelize the for loop.
When I inspect the network requests, as all the resources are in the 1rst graph, only one request to https://apiprod.happy-dev.fr/clients/ is made
Ah ah, cool!!! We were all hoping you'd say that. The team will celebrate that response :D
Hi @RubenVerborgh,
Any news here?
This one is a priority for us since it is turning our apps into lazy slugs :) Don't hesitate to tell us if you think we can help.
Don't hesitate to tell us if you think we can help.
Any profiling or insights where time is being spent, would help me get this solved faster. Booked time for this early next week.
I don't know if it helps but here are some observations:
await solid.data.context.extend(base_context)
const resource = solid.data["https://apiprod.happy-dev.fr/clients/1/"];
console.time();
await resource.name;
console.timeEnd(); // first call, need to request server: ~150-200ms
console.time();
await resource.img;
console.timeEnd(); // no need to request server: ~10ms
console.time();
await resource['http://happy-dev.fr/owl/#img']; // with full path, same time to resolve: ~10ms
console.timeEnd();
// same observations with this syntax
console.time();
const name = await solid.data["https://apiprod.happy-dev.fr/clients/2/"].name;
console.log(name.toString());
console.timeEnd(); // ~200ms
console.time();
const img = await solid.data["https://apiprod.happy-dev.fr/clients/2/"].img;
console.log(img.toString());
console.timeEnd(); // ~10ms
// and same without extending our context
const res = solid.data["https://apiprod.happy-dev.fr/clients/3/"];
console.time();
console.log((await res['rdfs:label']).toString());
console.timeEnd(); // ~200ms
console.time();
console.log((await res['http://happy-dev.fr/owl/#img']).toString());
console.timeEnd(); // ~10ms
This is interesting indeed, looks like we're chasing some specific requests in particular. Thanks.
When testing the "without extending our context" example, I get consistently good performance in Node.js 12.6.0:
https://apiprod.happy-dev.fr/clients/: 445.242ms
https://apiprod.happy-dev.fr/clients/1/: 2.918ms https://apiprod.happy-dev.fr/clients/2/: 1.596ms https://apiprod.happy-dev.fr/clients/3/: 1.518ms https://apiprod.happy-dev.fr/clients/4/: 1.481ms https://apiprod.happy-dev.fr/clients/5/: 1.806ms https://apiprod.happy-dev.fr/clients/6/: 1.760ms https://apiprod.happy-dev.fr/clients/7/: 1.465ms https://apiprod.happy-dev.fr/clients/8/: 1.302ms https://apiprod.happy-dev.fr/clients/9/: 1.230ms https://apiprod.happy-dev.fr/clients/10/: 1.301ms https://apiprod.happy-dev.fr/clients/11/: 1.234ms https://apiprod.happy-dev.fr/clients/12/: 1.222ms https://apiprod.happy-dev.fr/clients/13/: 1.556ms https://apiprod.happy-dev.fr/clients/14/: 1.379ms https://apiprod.happy-dev.fr/clients/15/: 3.331ms https://apiprod.happy-dev.fr/clients/16/: 1.756ms https://apiprod.happy-dev.fr/clients/17/: 1.573ms https://apiprod.happy-dev.fr/clients/18/: 1.355ms https://apiprod.happy-dev.fr/clients/19/: 1.262ms https://apiprod.happy-dev.fr/clients/20/: 1.478ms https://apiprod.happy-dev.fr/clients/21/: 1.408ms https://apiprod.happy-dev.fr/clients/22/: 1.378ms https://apiprod.happy-dev.fr/clients/23/: 1.483ms https://apiprod.happy-dev.fr/clients/24/: 1.281ms https://apiprod.happy-dev.fr/clients/25/: 1.314ms https://apiprod.happy-dev.fr/clients/26/: 2.273ms https://apiprod.happy-dev.fr/clients/27/: 1.299ms https://apiprod.happy-dev.fr/clients/28/: 1.477ms https://apiprod.happy-dev.fr/clients/29/: 1.282ms https://apiprod.happy-dev.fr/clients/30/: 1.580ms https://apiprod.happy-dev.fr/clients/31/: 1.331ms https://apiprod.happy-dev.fr/clients/32/: 3.948ms https://apiprod.happy-dev.fr/clients/33/: 1.317ms https://apiprod.happy-dev.fr/clients/34/: 1.268ms https://apiprod.happy-dev.fr/clients/35/: 1.332ms https://apiprod.happy-dev.fr/clients/36/: 1.316ms https://apiprod.happy-dev.fr/clients/37/: 1.244ms https://apiprod.happy-dev.fr/clients/38/: 1.394ms https://apiprod.happy-dev.fr/clients/39/: 1.330ms https://apiprod.happy-dev.fr/clients/40/: 1.471ms https://apiprod.happy-dev.fr/clients/41/: 1.430ms https://apiprod.happy-dev.fr/clients/42/: 1.130ms https://apiprod.happy-dev.fr/clients/43/: 1.132ms https://apiprod.happy-dev.fr/clients/44/: 1.092ms https://apiprod.happy-dev.fr/clients/46/: 1.167ms https://apiprod.happy-dev.fr/clients/47/: 1.102ms https://apiprod.happy-dev.fr/clients/48/: 1.127ms https://apiprod.happy-dev.fr/clients/49/: 1.108ms https://apiprod.happy-dev.fr/clients/50/: 1.078ms https://apiprod.happy-dev.fr/clients/51/: 1.099ms https://apiprod.happy-dev.fr/clients/52/: 1.130ms https://apiprod.happy-dev.fr/clients/53/: 1.099ms https://apiprod.happy-dev.fr/clients/54/: 1.086ms https://apiprod.happy-dev.fr/clients/57/: 1.298ms https://apiprod.happy-dev.fr/clients/58/: 1.237ms https://apiprod.happy-dev.fr/clients/59/: 1.181ms https://apiprod.happy-dev.fr/clients/61/: 1.307ms https://apiprod.happy-dev.fr/clients/63/: 1.446ms https://apiprod.happy-dev.fr/clients/64/: 2.788ms https://apiprod.happy-dev.fr/clients/65/: 1.138ms https://apiprod.happy-dev.fr/clients/66/: 1.084ms https://apiprod.happy-dev.fr/clients/67/: 1.031ms https://apiprod.happy-dev.fr/clients/68/: 1.433ms https://apiprod.happy-dev.fr/clients/69/: 1.071ms https://apiprod.happy-dev.fr/clients/70/: 0.975ms https://apiprod.happy-dev.fr/clients/72/: 0.947ms https://apiprod.happy-dev.fr/clients/73/: 0.937ms https://apiprod.happy-dev.fr/clients/75/: 0.936ms https://apiprod.happy-dev.fr/clients/76/: 1.142ms https://apiprod.happy-dev.fr/clients/77/: 0.993ms https://apiprod.happy-dev.fr/clients/78/: 1.033ms https://apiprod.happy-dev.fr/clients/79/: 1.311ms https://apiprod.happy-dev.fr/clients/: 445.242ms
So two questions:
- On what platform did you measure?
- Could I have your extended JSON-LD context (if the problem is there)?
I am testing in a browser (Chrome 78). Without extending our context, with this code:
const container = solid.data["https://apiprod.happy-dev.fr/clients/"];
console.time(container.toString())
for await (const r of container.ldp_contains) {
console.time(r.toString())
await r['rdfs:label']
console.timeEnd(r.toString())
}
console.timeEnd(container.toString())
I get different results than yours:
https://apiprod.happy-dev.fr/clients/: 1088.90087890625ms
https://apiprod.happy-dev.fr/clients/1/: 10.197998046875ms
https://apiprod.happy-dev.fr/clients/2/: 9.509033203125ms
https://apiprod.happy-dev.fr/clients/3/: 15.14794921875ms
https://apiprod.happy-dev.fr/clients/4/: 9.77783203125ms
https://apiprod.happy-dev.fr/clients/5/: 8.005126953125ms
https://apiprod.happy-dev.fr/clients/6/: 9.4130859375ms
https://apiprod.happy-dev.fr/clients/7/: 7.76416015625ms
https://apiprod.happy-dev.fr/clients/8/: 8.996826171875ms
https://apiprod.happy-dev.fr/clients/9/: 7.68896484375ms
https://apiprod.happy-dev.fr/clients/10/: 10.088134765625ms
https://apiprod.happy-dev.fr/clients/11/: 9.110107421875ms
https://apiprod.happy-dev.fr/clients/12/: 7.708984375ms
https://apiprod.happy-dev.fr/clients/13/: 9.901123046875ms
https://apiprod.happy-dev.fr/clients/14/: 8.379150390625ms
https://apiprod.happy-dev.fr/clients/15/: 8.369873046875ms
https://apiprod.happy-dev.fr/clients/16/: 12.80322265625ms
https://apiprod.happy-dev.fr/clients/17/: 20.765869140625ms
https://apiprod.happy-dev.fr/clients/18/: 9.837890625ms
https://apiprod.happy-dev.fr/clients/19/: 9.588134765625ms
https://apiprod.happy-dev.fr/clients/20/: 8.70068359375ms
https://apiprod.happy-dev.fr/clients/21/: 7.68505859375ms
https://apiprod.happy-dev.fr/clients/22/: 7.837646484375ms
https://apiprod.happy-dev.fr/clients/23/: 7.675048828125ms
https://apiprod.happy-dev.fr/clients/24/: 7.82080078125ms
https://apiprod.happy-dev.fr/clients/25/: 9.09814453125ms
https://apiprod.happy-dev.fr/clients/26/: 7.682861328125ms
https://apiprod.happy-dev.fr/clients/27/: 8.43994140625ms
https://apiprod.happy-dev.fr/clients/28/: 7.598876953125ms
https://apiprod.happy-dev.fr/clients/29/: 7.510986328125ms
https://apiprod.happy-dev.fr/clients/30/: 7.52392578125ms
https://apiprod.happy-dev.fr/clients/31/: 6.930908203125ms
https://apiprod.happy-dev.fr/clients/32/: 13.077880859375ms
https://apiprod.happy-dev.fr/clients/33/: 16.430908203125ms
https://apiprod.happy-dev.fr/clients/34/: 9.43603515625ms
https://apiprod.happy-dev.fr/clients/35/: 44.575927734375ms
https://apiprod.happy-dev.fr/clients/36/: 10.1259765625ms
https://apiprod.happy-dev.fr/clients/37/: 7.884033203125ms
https://apiprod.happy-dev.fr/clients/38/: 7.990966796875ms
https://apiprod.happy-dev.fr/clients/39/: 7.700927734375ms
https://apiprod.happy-dev.fr/clients/40/: 7.747802734375ms
https://apiprod.happy-dev.fr/clients/41/: 8.593017578125ms
https://apiprod.happy-dev.fr/clients/42/: 10.65673828125ms
https://apiprod.happy-dev.fr/clients/43/: 11.967041015625ms
https://apiprod.happy-dev.fr/clients/44/: 8.828125ms
https://apiprod.happy-dev.fr/clients/46/: 8.567138671875ms
https://apiprod.happy-dev.fr/clients/47/: 8.598876953125ms
https://apiprod.happy-dev.fr/clients/48/: 8.014892578125ms
https://apiprod.happy-dev.fr/clients/49/: 8.022216796875ms
https://apiprod.happy-dev.fr/clients/50/: 7.285888671875ms
https://apiprod.happy-dev.fr/clients/51/: 10.23974609375ms
https://apiprod.happy-dev.fr/clients/52/: 7.982177734375ms
https://apiprod.happy-dev.fr/clients/53/: 8.64990234375ms
https://apiprod.happy-dev.fr/clients/54/: 8.32080078125ms
https://apiprod.happy-dev.fr/clients/57/: 7.7568359375ms
https://apiprod.happy-dev.fr/clients/58/: 9.184814453125ms
https://apiprod.happy-dev.fr/clients/59/: 8.089111328125ms
https://apiprod.happy-dev.fr/clients/61/: 10.52490234375ms
https://apiprod.happy-dev.fr/clients/63/: 10.336669921875ms
https://apiprod.happy-dev.fr/clients/64/: 8.001953125ms
https://apiprod.happy-dev.fr/clients/65/: 8.064208984375ms
https://apiprod.happy-dev.fr/clients/66/: 7.955810546875ms
https://apiprod.happy-dev.fr/clients/67/: 8.31396484375ms
https://apiprod.happy-dev.fr/clients/68/: 7.802001953125ms
https://apiprod.happy-dev.fr/clients/69/: 9.5849609375ms
https://apiprod.happy-dev.fr/clients/70/: 10.0341796875ms
https://apiprod.happy-dev.fr/clients/72/: 8.09912109375ms
https://apiprod.happy-dev.fr/clients/73/: 10.044921875ms
https://apiprod.happy-dev.fr/clients/75/: 7.333984375ms
https://apiprod.happy-dev.fr/clients/76/: 8.4609375ms
https://apiprod.happy-dev.fr/clients/77/: 8.4951171875ms
https://apiprod.happy-dev.fr/clients/78/: 7.4658203125ms
https://apiprod.happy-dev.fr/clients/79/: 11.096923828125ms
https://apiprod.happy-dev.fr/clients/: 1088.90087890625ms
Here is the context I used:
const base_context = {
'@vocab': 'http://happy-dev.fr/owl/#',
rdf: 'http://www.w3.org/1999/02/22-rdf-syntax-ns#',
rdfs: 'http://www.w3.org/2000/01/rdf-schema#',
ldp: 'http://www.w3.org/ns/ldp#',
foaf: 'http://xmlns.com/foaf/0.1/',
name: 'rdfs:label',
acl: 'http://www.w3.org/ns/auth/acl#',
permissions: 'acl:accessControl',
mode: 'acl:mode',
email: 'http://happy-dev.fr/owl/#email',
};
Thanks, will test on Chrome! Although it's the same V8 engine, so I wonder what goes wrong.
Added comparative tests to the branch https://github.com/solid/query-ldflex/tree/test/45-performance. Run in node with node test.js; in browser with npm start demo.
I've traced the problem back to Comunica: it is the this._engine.query(sparql, { sources }) call in to Comunica in LDflex-Comunica that is slower in both Firefox and Chrome compared to Node.js. Assigning to Comunica people so they can trace on their end.
My first suspect was transpiling: perhaps the transpiled version of asynchronous iteration is slower than the native version. However, the same transpiled version is used for browsers and Node.js (I expect this to be the case all the way down Comunica as well). So I suspect the problem is rather in a shim.
Thank @RubenVerborgh for your time here.
@rubensworks, @joachimvh: Let us know if we can help you finding out why the query function is being slow in browsers. Don't we polyfill anything in it?
@rubensworks, @joachimvh: Any good news you would like to share with us? :-)
Let us know if we can help you finding out why the
queryfunction is being slow in browsers.
I think it is a shim or polyfill indeed. If you could identify the different code being called in command-line or browser, that would definitely help. Once possible example could be doing a loop of 1000 await solid.data["https://apiprod.happy-dev.fr/clients/2/"].img with a profiler, and comparing the results.
I just did the above; I see a quite some time spent in setImmediate. Perhaps we are using a non-optimal shim for that one.
Indeed, the function is not supported by both Chrome and Firefox : https://developer.mozilla.org/en-US/docs/Web/API/Window/setImmediate
I'll dig deeper tomorrow afternoon.
Our code relies heavily on setImmediate, which is fast in Node.js, but I suspect insufficiently so in browser shims. Tried replacing it with requestAnimationFrame, but that didn't go great either.
For simple calls such as await solid.data["https://apiprod.happy-dev.fr/clients/2/"].img, we apparently use around 60 setImmediate calls (in asynciterator alone). That's definitely more than the browser shim can handle. We should ~~either improve the browser shim, or~~ (not much room for improvement) reduce that number.
In the meantime, @happy-dev, could you check how far asyncMap with concurrency (8–128) gets you (instead of for await)? There's no need to execute those in sequence anyway; I've seen some gains from parallel.
@matthieu-fesselier could you please check that?
@RubenVerborgh any idea how long a fix could take? Sorry about the pressure, but it's blocking all of our applications. :)
@sylvainlb No budget is currently assigned to LDflex, so it's best effort. We are looking into ways to fund a developer on Comunica and related projects, such that they do not primarily depend on efforts by researchers. Any help or suggestions there are definitely welcome.
I think the parallel road is definitely a good one for your applications. Even if the duration of individual calls is reduced, it still makes sense to perform multiple operations in parallel such that the longer ones do not block the shorter ones.
As for the duration of a fix, in addition to the above budget constraints, the main Comunica developer is currently on holidays. Given that my suspect is the setImmediate mechanism, which is at the heart of the stream communication, I'm afraid that this will take some serious effort. The use case that uncovered this performance bottleneck involves a) a larger sequence of simple queries b) in the browser, whereas our performance testing has focused on complex queries, and we benchmark on server environments. This explains why the additional couple of milliseconds per request (which of course easily add up) was not caught before.
I plan to perform some testing tonight in order to create a more specific issue in the appropriate repository.
Thanks @RubenVerborgh for the feedback. We totally understand the situtation. Can we help with a resource? We could ask someone to look into it.
Could you elaborate on what you mean by "parallel road"? I'm not sure to follow you.
Thank you for your efforts. Let us know how we can help. We're definitely willing to put some effort on this issue, so if you know where our efforts would be best used, we'll do as much as we can.
Just fyi, apparently setImmediate is deprecated and will not make it into the standards. It's probably a good idea to get rid of it if we can.
MDN suggests replacements: https://developer.mozilla.org/en-US/docs/Web/API/Window/setImmediate#Notes
Can we help with a resource? We could ask someone to look into it.
What we really want to find out is: what's happening differently in the browser? The aforementioned setImmediate is one difference that popped up, but further experiments have made me think that something else is contributing more significantly. Given the very small timescale (it's literally a couple of milliseconds difference per query), it's hard to find out what that is. My main frustration is that I currently see close to 50% idle time in a performance test. Any help with that is appreciated.
I am writing up an issue for Comunica; will link it into this thread.
Just fyi, apparently setImmediate is deprecated and will not make it into the standards.
setImmediate will indeed not make it into browsers; but it is part of Node.js, for which we write Comunica and where it is well supported. The suggested replacements by MDN are actually those that are currently used in the browser version of LDflex, where webpack picks the right alternative (typically postMessage).
I have experimented replacing setImmediate with alternative implementations to measure its effect. However, when I use the same alternatives on both Node.js and the browser, Node.js is still faster, which is the reason why I suspect that setImmediate is not the primary cause (although we definitely want to reduce the number of calls to it in general).
Could you elaborate on what you mean by "parallel road"? I'm not sure to follow you.
The current code is for … awaiting through every r of container.ldp_contains sequentially. So they all have to wait for each other. Whereas if you'd do them in parallel (for instance with asyncMap linked above), then some of the waiting time overlaps.
In the above case specifically, you could also just do for await (const r of container.ldp_contains.img) (but I expect that this code is part of a larger block, where this might not be possible).
I think it's already clear for you, but we use ldflex in the browser without WebPack. I don't know if it changes something to what you just said.
The current code is for … awaiting through every r of container.ldp_contains sequentially. So they all have to wait for each other. Whereas if you'd do them in parallel (for instance with asyncMap linked above), then some of the waiting time overlaps.
@matthieu-fesselier what do you think?
I think it's already clear for you, but we use ldflex in the browser without WebPack.
You're likely using some kind of packaging, or it wouldn't work at all 🙂 What is your packaging method?
Regardless, the problem occurs with webpack as well.
Another possibility is that we build a mechanism for preloading certain properties. Something like container.ldp_contains.children({ img: true }) or so, which would load them all in batch. However, I wanted to keep the individual .img calls as light as possible (and that works in Node.js) to avoid the need of such a call.