CPU usage increases over time on RasPi 3 B by using .windowTime()

[olivermue]

RxJS version: 5.0.0-beta.10 - 5.0.0-rc.1

Code to reproduce:
(see attachement)
The line that causes the issue:

let subscription = observable.windowTime(100).subscribe(values => { /* do nothing  */ });

Expected behavior:
The cpu usage stays stable.

Actual behavior:
The cpu usage slowly climbs up to 200%.

Additional information:
Okay, let's explain a little more. 😉

I'm running node.js 6.9.1 on my RasPi 3 B and have a node instance that gets data from outside through socketcan or socket.io. This incoming data will be pushed into an Observable and then further consumed. But I seen that after a while (10 minutes to 3 hours) the cpu usage is constantly climbing up till it reaches 200% and everything gets really slow. So I stripped down the code to find the root cause and attached you'll find the result of these investigations.

The attached script has something around 90 lines and can be started in four modes, depending on the given command line argument being server, client-empty, client-rx or client-rx-window. To reproduce the problem, the script must be started once with parameter server and once with parameter client-rx-window. Afterwards you can examine the cpu usage through top.

node app.js server &
node app.js client-rx-window &
top

When the scripts starting the server will run with around 30% cpu usage and the client around 40-50%. After a while you'll see the client is slowly climbing up (reaching 60% and on) and if you wait long enough it will hit the 200%.

Just to prove, that the problem really comes from the .windowTime(), the other clients are there as well. The client-empty doesn't use rxjs at all, it just receives the data from socket.io and calls an empty lambda function socket.on(channelName, () => { });. The client-rx directly subscribes with an empty lambda observable.subscribe(values => { /* do nothing */ }); to the observable without putting the .windowTime() in between.

I tested the same scripts also on a Ubuntu 15 within a VMware image to check if the problem really comes from the library and guess what, there the problem does not occur. 😟

So even that I cannot reproduce this problem on a different hardware (like desktop pc) I want to inform you about this issue and maybe someone has a clue why using the .windowTime() leads to such problems, if the observer.next() call will be triggered from an external event like incoming data through socket.io or socketcan.

app.zip

[trxcllnt]

@olivermue does this happen with any other time-based operators (such as auditTime or throttleTime)? Knowing that can help us determine whether we should start looking at the async scheduler, or just the windowTime operator.

[olivermue]

Just ran some tests: By using .auditTime() or .throttleTime() the problem does not occur.

[olivermue]

I made further tests on a different hardware and there the problem occurs too for .windowTime()!

The other hardware was also ARM based:

processor : 0
model name : ARMv7 Processor rev 10 (v7l)
BogoMIPS : 6.00
Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpd32
CPU implementer : 0x41
CPU architecture: 7
CPU variant : 0x2
CPU part : 0xc09
CPU revision : 10

And the used node version was v4.2.6.

So I can reproduce the same error on a different hardware (but also ARM based) and a different node version.

[trxcllnt]

@olivermue thanks for testing further. Glad to know it's probably not an issue with the Scheduler architecture! will look into windowTime when I get some time next week.

[jayphelps]

When trying to reproduce on Ubuntu 15 can you also confirm whether or not you were using node 6.9.1 exactly? As you can guess, it's pretty unusual for JavaScript code to cause this sort of disparity in CPU clime in the same node version but differing OS/hardware, so wanna double check it's not just some issue with that node version on that hardware/OS. If that is the case, we can still look into what triggers it and see if we can work around it.

It's also gonna be hard to reproduce since most of us probably don't have a raspberry pi. 😄 so we may have to have you try some things for us, assuming it's not also reproducable on our desktops.

[daixtrose]

Probably it is still a good idea to grab a Raspi 3 and reproduce it there in order to isolate the culprit. Do you need a donation?

[chriscareycode]

Tested on a Raspberry Pi 3 with NodeJS 7.0 with similar results. I'm seeing about 200% CPU scattered across all 4 CPUs. Working on getting some flame graphs of processor usage with perf which hopefully can turn up some clues.

[jayphelps]

@daixtrose Thanks for the offer! @chriscareycode is a co-worker of ours who has some Pi 3's (obviously) so we don't need a donation anymore.

[daixtrose]

@chriscareycode I am so curious what triggers this bug, so please also report how you try to catch it. Many things to learn from this issue ...

[trxcllnt]

Looking over the windowTime operator, it seems like if there's only a windowTimeSpan argument, closed windows aren't removed from the windows list. Also, I don't see an _unsubscribe to clean up the windows on disposal. Not sure if this is the source of this bug, but it does seem this is generally problematic.

[benlesh]

I'd bet it not being removed from the windows list is the source of the CPU usage issues. Because that means the list of what it has to loop over is going to grow over time. It's still going to try to next into those dead observers, which executes some code.

I'll add some fixes to this and will see if that resolves the issue.

[daixtrose]

@Blesh Any update on this issue?

[kwonoj]

@daixtrose @olivermue I believe #2278 fixes issues when using windowTime with timespan only. Just need anyone's verification with latest 5.1.0.

[daixtrose]

@kwonoj glad to hear this. Unfortunately our Raspi got some hardware issue today and I need to buy another one first, so if @Blesh still has a test system I would be grateful if he can confirm issue can be closed.

[chriscareycode]

I have a Raspberry Pi 3 here with the cpu-issue code to reproduce still on it. I re-ran the original client and server code and saw the node process increase up to 99% CPU after 5 to 10 minutes of running.

Next I copied the cpu-issue folder and updated RxJS to 5.1.0 and ran the test again. After 10 minutes of running, the node processes are each hovering below 50% CPU and are not increasing. So far so good.

[daixtrose]

Cool. @chriscareycode could you please
a) check if you see a diff in memory consumption?
b) let the new setting run a little bit longer. Just to be sure the leak is not only reduced, but gone.

[chriscareycode]

Did not see a difference in memory consumption.

The new code ran for about 2 hours and did not increase above 50% CPU

[kwonoj]

I'm going to close the issue as I believe this specific issue itself has fixed with the latest release.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.