parseAsync Sometimes blocks for a *long* time

[teetering]

I've been testing the library recently and while it sometimes works well, the call to parseAsync sometimes blocks for a long long time (ex 1 minute). I'm not talking about the time to parse the JSON string, but rather the blocking time before parseAsync returns (and before the parse takes place).

I'm still trying to figure out what's tickling it. Perhaps it is the same as mentioned here:

#18

Regardless, this obviously defeats the whole point of the library. I think it's important to give a warning up front at the top of the README that this library shouldn't be used in any production systems. This will surely bite a lot of people.

[gireeshpunathil]

do you have a program that recreates the issue?

I think it's important to give a warning up front at the top of the README that this library shouldn't be used in any production systems.

the whole point of the library is to use in production. Instead of documenting defects, I would rather fix it. if you have a stable recreate, pls pass it on, that way you will also be part of improving this module!

[teetering]

First of all I want to thank you for your work on this library; incredible effort! I know that it is not an easy endeavor, and I personally believe that it is a critical piece that is conspicuously missing from the node native functionality.

That said, I do think it's important to state explicitly up front that it is not production ready (until it is). In my example (from the real-world), yieldable-json is causing the event loop to block for close to 1 minute which would obviously be fatal to any production system.

parse-test.tar.gz

Attached is a simple repro. The program starts with
setInterval(() => { console.log('*heartbeat*') }, 1000);
Here is the output when run it on my computer:

2ms ... Begin
5ms ... About to stringify
16ms ... Stringified
0ms ... About to call yj.parseAsync
16683ms ... Called yj.parseAsync
*heartbeat*
*heartbeat*
22245ms ... Finished parsing err:false data:true
*heartbeat*
*heartbeat*
*heartbeat*
...

It demonstrates two big problems (which I believe are possibly unrelated):

• 16683ms ... Called yj.parseAsync : The call to yj.parseAsync blocks for 17 seconds. I believe that this is related to Potential to block when parsing huge string with lots of escaped characters #18 . I can reproduce this with just the first (long) string in my example JSON.

• 22245ms ... Finished parsing : Parsing took 22 seconds. That's a long time, but that's not the biggest problem. The big problem is that the *heartbeat* messages are not being output every second while the parsing is taking place, I assume due to starvation. (I can only repro this one with the rest of the JSON in my example, not with just the long string.)

[gireeshpunathil]

@teetering - thanks, I am able to reproduce the issue you reported. stay tuned, I will see what going on.

[JohnBatts418]

Hi, Just came across this and hit a similar problem. Is there any update on this?

[gireeshpunathil]

haven't completed my analysis. expect some response in a week's time.

[gireeshpunathil]

an intermin update:

the JSON object in the given test case had a string which is more than 800000 characters long among other things. This is the string which is taking 99% of the time in function normalizeUnicodedString

yieldable-json/yieldable-parser.js

Line 67 in 5809572

let normalizeUnicodedString = () => {

when I replaced that with a small token, the test completed in less than a second.

the purpose of this function is to parse an incoming string and make sure any escape characters are properly accommodated. Looks like this function can be optimised.

I will study the function to see what can be done better. Meanwhile, feel free to propose PRs if you have ideas!

[gireeshpunathil]

@JohnBatts418 - can you share your test case too? I want to examine and confirm that your issue is same as this one.

[latish]

Running into the same issue of very slow performance when JSON object has a really long string in it.

[gireeshpunathil]

thanks for the update. right now running short on bandwidth; PRs welcome!

[lukas8219]

@teetering In which machine are you running this benchmark? I am willing to spend sometime on this issue in the next month but in my machine it takes 2seconds. I wanna simulate in a CPU constrained environment.

The event-loop blocking I am able to repro tho

[teetering]

@teetering In which machine are you running this benchmark? I am willing to spend sometime on this issue in the next month but in my machine it takes 2seconds. I wanna simulate in a CPU constrained environment.

The event-loop blocking I am able to repro tho

Thank you for looking! After your message, I tried with two different hardware architectures and got vastly different performance results, which I guess explains why you don't see the same as me.

My very bad results above are on Ubuntu 22.04.4 LTS (Linux 6.5.0-44-generic x86-64) running on an Intel(R) Xeon(R) CPU E5-2630 v3 @ 2.40GHz (which is typically quite decent).

On the other hand, on a Mac M1, I'm getting much better performance (though, as you say, still with problems blocking the loop):

2ms ... Begin
5ms ... About to stringify
7ms ... Stringified
0ms ... About to call yj.parseAsync
2208ms ... Called yj.parseAsync
*heartbeat*
*heartbeat*
3103ms ... Finished parsing err:false data:true
*heartbeat*
*heartbeat*

[lukas8219]

This is very interesting.

So per my investigations, reinforcing what @gireeshpunathil said, the problem comes from the normalization. But mostly, it seem like a hot-loop calling indexOf into huge strings. I am facing couple issues with consistency as the current Unit Test don't catch all the cases.

But thanks from letting me know about the architecture specificities.

My PC is also an MacBook - M3 Max Pro and I see the exact 2-3seconds delay you just posted @teetering

I'll first try to fix the event-loop being blocked. And then I'll try to look for AMD specific issues (which then seems really tough)

Again, just reinforcing this is an open source contribution - so I am not promising anything 🙏🏻 rather trying to help - as this is also similar to our use cases

[lukas8219]

Update:

Got the fix working - by naively splitting the indexOf to a by-chunk generator style. It does decrease performance but manages to unblock the event-loop.

Next steps are mainly checking current changes in AMD/Intel CPU's and ensuring the performance bottlenecks are the same.

For reference:

The parse-test folder shared - executes in total 4.8s in my local machine. With the eventloop fix, it takes 5.5-6s. I am assuming it could be much faster if the intensity parameter is bumped - but again that would hit eventloop.

[gireeshpunathil]

@lukas8219 - thanks for pursuing this and coming up with a solution. I will continue watching the PR, let me know when it is in a reviewable state.

[lukas8219]

@teetering Can you share which Node version you were running when you did both benchmarks? Intel vs Apple Chip/ARM? I've only ran the benchmark using virtualized environments (ie LimaCTL for MacOS) and I am not seeing the issue using Node v20.16.0 with Ubuntu AMD.

Using this images

- location: "https://cloud-images.ubuntu.com/releases/22.04/release/ubuntu-22.04-server-cloudimg-amd64.img"
  arch: "x86_64"
- location: "https://cloud-images.ubuntu.com/releases/22.04/release/ubuntu-22.04-server-cloudimg-arm64.img"
  arch: "aarch64

I'll have to spin up an VM for to properly benchmark this - but I am afraid this might be much more related to Node internal API's.

Performance was not great - but still around 7/8s - both using master and my code

[teetering]

@lukas8219 I am testing on v20.16.0 ...

[lukas8219]

Got reproable results in a non-VM using GCP. My code fixed the problem but costed ~2 seconds more. Let's wait for @gireeshpunathil thought for the trade-offs so I can continue cleaning up the code and settling up the PR

[gireeshpunathil]

@lukas8219 - pls continue the cleanup work and undraft the PR when you feel it is ready for review. given that it has fixed the original problem, I would deem that the tradeoff is acceptable - we could find ways to eliminate that too, in future PRs!

[lukas8219]

@gireeshpunathil The PR is ready for review!