Ratchet on 100% CPU load

[lucasfecko]

Hi,

We are having an issue with running a ratchet server in production environment. Sometimes the server (process) just skyrockets to server load using 97-100% of one core on server. Server is running on PHP 5.6.0 with PHP-FPM and Nginx.

We are using the latest repositories currently available:
cboden/ratchet v0.3.2
react/event-loop v0.4.1
react/socket v0.4.2
react/stream 0.4.2

Libevent library is installed and ratchet is using this library (var_dump($server->loop); outputs the libevent loop). I know there is an issue about this here but it was closed an I am still experiencing it. The issue occurs randomly, sometimes in the middle of the night, but today it occured around evening and I was promptly informed. I restarted the proces but after a few seconds it skyrocketed again (the JS client is implementing a keepalive system and thus is trying to reconnect every few seconds). After many restarts it still used the full CPU, I was able to just look and try to restart it every few minutes. After around 30 minutes and many restarts it returned back to normal. The traffic on this prcoess is pretty big, with around 400-700 clients connected at the same time. I am unable to track what causes the issue, but from my understanding something enters the loop and causes a lag in it. Because it started today right after restart, I think there was a client that somehow connected the wrong way and something caused a leak or error, that in loop used the full CPU. Just my guess.

While it is on full load, some clients are connected and new clients can't connect. I am stressed out because the app is in production and real-time events are a pretty important and big part of it and the whole solution depends on it.

I cannot run an XDebug on production, is there any other way I can track what causes this can have, or any workaround to solve this?

Thank you for your replies.

[cboden]

Server is running on PHP 5.6.0 with PHP-FPM and Nginx

I just want to confirm you're not launching the WebSocket process via an HTTP connection?

---

To help debugging can you turn up the error level reporting in your script and turn on display errors? They should get sent to STDOUT and you can log them to a file somewhere. See if there are any errors being reported.

[lucasfecko]

Thank you for your response, no, process is launched in CLI and maintained by Supervisor, I have just asked for sudo password so I can work from home and make appropriate changes, will respond as soon as possible.

[cboden]

Supervisor will generate logs from STDOUT and STDERR for you automatically. Just make sure your error reporting is paranoid in your script:

ini_set('display_errors', 1);
error_reporting(E_ALL);

[cboden]

Possibly related to reactphp/stream#2

[lucasfecko]

I have added the settings to PHP file that starts the process, supervisor is keeping the process running and not reseting it, there are various stderr files in supervisor log directory but all are 0 bytes.

Also the main supervisord.log file doesn't show any errors, just my resets and starts.

[lucasfecko]

I am trying to quickly locate a problem, so I have placed various echo's with different messages in each condition where Buffer.php from react/stream can emit an error. Came up with this, when running the process from console, so the echo output is coming back from line 120 in Buffer.php:

        if (0 === strlen($this->data)) {
            $this->loop->removeWriteStream($this->stream);
            $this->listening = false;
            $this->emit('full-drain', [$this]);
        }

[cboden]

I don't quite understand your last comment. That chunk of code removes itself from the EventLoop so it's one less resource to poll. It gets re-attached if there is data to be written.

Do you have any code in your onError methods that implement a Ratchet interface? Can you echo any $e->getMessage(). I _think_ any errors from the write buffer should bubble up there.

[lucasfecko]

Yes, I have implemented an error log in onError method, but last message there was an hour ago and it was:

Tried to write to closed stream.

There aren't any other messages in error log than this.

[cboden]

Is your CPU currently at 100%? Or was that message logged when the CPU got to 100%? Is that message repeated frequently?

[lucasfecko]

That message was logged when my CPU wasn't on 100% at the time, judging from the time. The CPU is at 100% currently, and was in this state this past hour. Currently while experiencing the bug there aren't any logged messages. Message is not repeated frequently, there are a few (10-15) per hour.

[lucasfecko]

As of now, issue disappeared again and process is running normally. Issue disappeared after restart, one of many was successful somehow.

And it's back again :/.

[cboden]

Intermittent issues like this are typically caused by edge case network behaviour and race conditions. They're difficult to track down because the trigger is outside "normal" behaviour. I'd recommend keeping any eye on your CPU utilization and if it spikes post the latest logs. A race condition is most likely causing an event to constantly be put back on the event loop.

[lucasfecko]

The problem is, onError method logs are empty in times when this issue is occuring. Is there any additional logging I can set up to better track the behaviour?

[cboden]

Perhaps hard-coding some stuff in the React source code...but it would be difficult to determine when/where the problem comes from I would imagine. Perhaps trying to use strace? One user posted a log of it which helped me narrow down a previous CPU starvation bug.

[lucasfecko]

The process somehow cooled down itself just now for a few minutes. Time here just passed midnight and traffic lowered. So far thank you for your tremendous and fast support @cboden, I will post a ctrace log when It occurs again. Thank you very much!

[lucasfecko]

So it occured again and I ran an strace output to file for a few seconds. The output can be found here. The interesting part of the output seems to be these lines, wich occurs many times per second:

poll([{fd=10, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=10, revents=POLLIN}])
accept(10, 0x7fff87fa6260, [128])       = -1 EMFILE (Too many open files)

Wich indicates there are too many open files. But from my logs the peak of users connected (I am logging the peak in onOpen method) was 316 at the time error started.

[cboden]

I know some systems have their open fd limit set to 256 by default. That would certainly be something to look into increasing.

[lucasfecko]

The default fd limit on our machine is 1024, we have increased the limit at the beginning for processes, but the crucial thing was, ratchet is running under supervisor, so supervisor's limits apply to ratchet too. Since I have increased the limits for supervisor 3 days ago, the error didn't occur.

What is unusual, there were never 1024 actual connections at the time, the polling system somehow spiked it to this number, and the CPU went uphill. I don't know if this issue is related to react directly.

Anyway, I have solved my problem by increasing the fd limit, so I am closing the issue as not directly related to your work @cboden. Thank you for your assistance!