100% CPU usage reading from 115200 baud serial port

[JohannesRudolph]

This may be a general node.js issue, but I'm keen to learn the experts opinion on this. We are using nodejs on an Arduino YUN (MIPS 400 MHz). The serial port sends data at 115200 baud (fully saturated).

When I run a simple serial program to just receive the data from the serial port (and do nothing with it), it maxes out the CPU at 100% (about 70% user, 30% system according to top):

'use strict';

var port = '/dev/ttyATH0';

var SerialPort = require("serialport").SerialPort;
var rs = new SerialPort(port, {
  baudrate: 115200,
  buffersize: 1024
});

rs.on('open', function () {
  console.log('port opened!');
});

rs.on('data', function (data) {
  // console.log(data);
});

The problem is, the program needs headroom to do a lot more than that and a simple ~14KB/s serial connection maxing out a 400Mhz CPU doesn't seem entirely right to me.

Sure enough, a simple cat /dev/ttyATH0 > /dev/null (note that this works on my system as the dev is configured for 115200 baud by default) results in around 15% CPU usage. cat /dev/ttyATH0 > /dev/ttyATH0 (piping RX to TX) works at around 5% (possibly due to saving kernel->user space copies).

So I dug deeper and tried to work with node.js fs and a statically allocated buffer.

var fs = require('fs');
fs.open(port, 'r', function (err, fd) {
  console.log('port opened! ' + err);

  var buffer = new Buffer(8),
    read;

  function readCb(err, bytesRead, buffer) {
    console.log(bytesRead);
    process.nextTick(read); // continue reading
  }

  read = function () {
    fs.read(fd, buffer, 0, buffer.length, null, readCb);
  };

  read();
});

Same results, 100% cpu according to top.

Now, I'm totally surprised by this. Increasing the buffer sizes didn't help in both cases either. Is there an inherent reason why Serialport/nodejs is so slow in just fetching the data from the serial port? Are there any performance tips you can offer? Or is the CPU usage reported by top just way off? (I believe this is not so, my investigations started because we were seeing massive lags in processing the serial data, to the tune of 10-20 seconds).

I assume @voodootikigod et. al. might have some insights to share from all those robot projects. Or is everyone using this on beefier hardware? (But still, doesn't seem right to me to max out a 400Mhz CPU for a measly serial port).

[reconbot]

This is a great find. What version of nodejs are you running?

[JohannesRudolph]

node --version is v0.10.28. Serialport 1.4.0 (I know it's a few versions behind but I get the same behavior with fs.read, so I do actually think it's a node.js problem. Probably related to libuv's handling of emulated async io with lots of syscalls requiring synchronization across condition variables etc.

Proof for this hypothesis with a test program running on a Netduino sending packets

50 bytes/packets 10ms sleep/packet -> 3.66kB/s received data rate = 31%usr 15%sys CPU
10 bytes/packets 2ms sleep/packet -> 3.35kB/s received data rate = 75%usr 20%sys CPU

So a smaller data rate yielding higher cpu usage. Node.js program identical between the two tests:

var port = '/dev/ttyATH0';

var SerialPort = require("serialport").SerialPort,
  net = require("net"),
  fs = require('fs');

var rs = new SerialPort(port, {
  baudrate: 115200
});

rs.on('open', function () {
  console.log("SerialPort opened");
});

var bytes = 0;

setInterval(function printStats() {
  console.log("throughput: " + bytes / 1024 + " kB/s");
  bytes = 0;
}, 1000);

rs.on('data', function (data) {
  bytes += data.length;
});

[JohannesRudolph]

A few further thoughts on this. I did also test whether the serial port is responsible for the huge delays we were seeing. Turns out that was not the case. I put in some hacked code to test how many event loop iterations I was able to get with the serial port at full speed. Basically the test program just schedules a chunk of work that takes exactly 0.1ms with setImediate. With the serial port disconnected, I get about 3000 such ticks/s (10000 would be the theoretical maximum) and top reads 100% usr cpu usage.

With the serial port at full blast, I get about such 900 ticks/s at 72%usr and 26%sys cpu usage. And here comes the weird part. If I remove the tick counting (remember, we're still processing the serial port data at full speed) I see the usr cpu usage at 64% but the sys usage up at 35%? So basically we're just shifting cpu from usr to sys if there's nothing else to do? spinlocks in libuv? wtf....

var port = '/dev/ttyATH0';

var SerialPort = require("serialport").SerialPort,
  net = require("net"),
  fs = require('fs');

var rs = new SerialPort(port, {
  baudrate: 115200
});

rs.on('open', function () {
  console.log("SerialPort opened");
});

var bytes = 0,
  ticks = 0,
  state = '0';

setInterval(function printStats() {
  console.log("throughput: " + bytes / 1024 + " kB/s");
  bytes = 0;
  console.log("0.1ms ticks: " + ticks + " tick/s");
  ticks = 0;
}, 1000);

rs.on('data', function (data) {
  bytes += data.length;

  var i,
    newState;

  for (i = 0; i < data.length; i += 1) {
    newState = data[i];
    if (newState !== state) {
      console.log(newState);
    }
    state = newState;
  }
});

// burn cpu for a specified number of milliseconds
function startSleeper(ms) {

  function sleep() {

    var startHr = process.hrtime();

    var diff = 0; // diff in milliesconds
    while (diff < ms) {
      var hrDiff = process.hrtime(startHr);
      diff = (hrDiff[0] * 1e9 + hrDiff[1]) / 1000; // from seconds to milliseconds
    }

    ticks += 1;
    setImmediate(sleep);
  }

  setImmediate(sleep);
}

startSleeper(0.1);

[fivdi]

I'd say 100% CPU usage is to be expected in this case. When opening the serial port in serialport_unix.cpp the following code fragments are executed:

int fd = open(data->path, flags);

options.c_lflag = 0; // Turns canonical input mode off
options.c_cc[VMIN]=1;
options.c_cc[VTIME]=0;

tcsetattr(fd, TCSANOW, &options);

Because the timeout is 0 and the minimum number of characters to read is 1, characters are read and passed back to the following event listener from the first post above as quickly and as often as possible:

rs.on('data', function (data) {
  // console.log(data);
});

The baudrate is 115200, so the port is receiving about 11520 characters a second. This means that there will be a small number of characters available for passing back to the event listener on every turn of the event loop so CPU usage will be 100%.

[JohannesRudolph]

How many ticks/s can we expect out of a nodejs event loop? 10.000ops/s doesn't sound too much from my point of view, even for a 400Mhz cpu.

So you're saying that serialport_unix delivers the bytes to nodejs one by one? The default buffer size is 256, so that buffer is then assembled in nodejs? Wouldn't it be more efficient to assemble the buffer in serialport_unix.cpp (or better, let the kernel handle it)?

I will have a detailed look at the serialport_unix.cpp code later today and see whether I can come up with a "fix" to achieve the performance that we need (e.g. by adjusting buffer sizes and similar).

[voodootikigod]

For details about VMIN/ VTIME, read through this: http://unixwiz.net/techtips/termios-vmin-vtime.html

tl;dr VMIN is the lowest we will settle for as a 'return value' while nbytes (buffer size) is what were ideally would like. nbytes is what read will always look for

Happy to change them, but what is your suggested change? We could add them to the parameters to allow you change as you see fit.

VMIN > 0 and VTIME = 0This is a counted read that is satisfied only when at least VMIN characters have been transferred to the caller's buffer - there is no timing component involved. This read can be satisfied from the driver's input queue (where the call could return immediately), or by waiting for new data to arrive: in this respect the call could block indefinitely. We believe that it's undefined behavior if nbytes is less then VMIN.

Chris Williams

@voodootikigod http://twitter.com/voodootikigod | GitHub http://github.com/voodootikigod

The things I make that you should check out: SaferAging http://www.saferaging.com/ | JSConf http://jsconf.com/ | RobotsConf http://robotsconf.com/ | RobotsWeekly http://robotsweekly.com/

Help me end the negativity on the internet, share this http://jsconf.eu/2011/an_end_to_negativity.html.

On Sat, Oct 25, 2014 at 10:11 AM, Johannes Rudolph <notifications@github.com

wrote:

How many ticks/s can we expect out of a nodejs event loop? 10.000ops/s doesn't sound too much from my point of view, even for a 400Mhz cpu.

So you're saying that serialport_unix delivers the bytes to nodejs one by one? The default buffer size is 256, so that buffer is then assembled in nodejs? Wouldn't it be more efficient to assemble the buffer in serialport_unix.cpp (or better, let the kernel handle it)?

I will have a detailed look at the serialport_unix.cpp code later today and see whether I can come up with a "fix" to achieve the performance that we need (e.g. by adjusting buffer sizes and similar).

— Reply to this email directly or view it on GitHub https://github.com/voodootikigod/node-serialport/issues/402#issuecomment-60484111 .

[JohannesRudolph]

Yeah, having them as advanced options would certainly help for the cases where the user knows what he's doing. Can you set up a branch with possible changes so I can give it a spin? I do unfortunately have no experience in writing custom node bindings.... (If I have some spare time I can take a stab at it myself, but that would probably not be before next week).

On Sat, Oct 25, 2014 at 4:26 PM, Chris Williams notifications@github.com wrote:

For details about VMIN/ VTIME, read through this: http://unixwiz.net/techtips/termios-vmin-vtime.html

tl;dr VMIN is the lowest we will settle for as a 'return value' while nbytes (buffer size) is what were ideally would like. nbytes is what read will always look for

Happy to change them, but what is your suggested change? We could add them to the parameters to allow you change as you see fit.

VMIN > 0 and VTIME = 0This is a counted read that is satisfied only when at least VMIN characters have been transferred to the caller's buffer - there is no timing component involved. This read can be satisfied from the driver's input queue (where the call could return immediately), or by waiting for new data to arrive: in this respect the call could block indefinitely. We believe that it's undefined behavior if nbytes is less then VMIN.

Chris Williams

@voodootikigod http://twitter.com/voodootikigod | GitHub http://github.com/voodootikigod

The things I make that you should check out: SaferAging http://www.saferaging.com/ | JSConf http://jsconf.com/ | RobotsConf http://robotsconf.com/ | RobotsWeekly http://robotsweekly.com/

Help me end the negativity on the internet, share this http://jsconf.eu/2011/an_end_to_negativity.html.

On Sat, Oct 25, 2014 at 10:11 AM, Johannes Rudolph < notifications@github.com

wrote:

How many ticks/s can we expect out of a nodejs event loop? 10.000ops/s doesn't sound too much from my point of view, even for a 400Mhz cpu.

So you're saying that serialport_unix delivers the bytes to nodejs one by one? The default buffer size is 256, so that buffer is then assembled in nodejs? Wouldn't it be more efficient to assemble the buffer in serialport_unix.cpp (or better, let the kernel handle it)?

I will have a detailed look at the serialport_unix.cpp code later today and see whether I can come up with a "fix" to achieve the performance that we need (e.g. by adjusting buffer sizes and similar).

— Reply to this email directly or view it on GitHub < https://github.com/voodootikigod/node-serialport/issues/402#issuecomment-60484111>

.

— Reply to this email directly or view it on GitHub https://github.com/voodootikigod/node-serialport/issues/402#issuecomment-60484528 .

[JohannesRudolph]

I have sent a pull request that adds the relevant settings as platform specific options. This fixes performance when I use fs.read on a correctly setup tty directly, however it still gives bad performance when used with node-serialport.

With my proposed changes and a serial port setup to use vmin=100 and vtime= 0 and a probe inserted into serialport.js, line 328, where the fs.read syscall to the OS takes place:

  fs.read(self.fd, self.pool, self.pool.used, toRead, null, function (err, bytesRead) {                                                                                                         
    console.log("fs.read returned " + bytesRead + " bytes");   

reading using node-serialport (test-serialport.js below)

fs.read returned 27 bytes
fs.read returned 25 bytes
fs.read returned 25 bytes

This is unexpected - we get less than vmin bytes (remember, vtime = 0) and still see 100% CPU usage. With a simple program (test-fs.js) that uses the exact same /dev/tyy (but without node-serialport) we see

fs.read returned 256 bytes
fs.read returned 101 bytes
fs.read returned 100 bytes

Note that 256 is what I pass to fs.read as desired size. So the first few requests are served from the OS buffer, so they may contain more than vmin bytes. This program runs with 20% CPU.

I confirmed that the settings on the serial port are identical for both programs using stty.

test-serialport.js

'use strict';

var port = '/dev/ttyATH0';

var SerialPort = require("serialport").SerialPort,
  net = require("net"),
  fs = require('fs');

var rs = new SerialPort(port, {
  baudrate: 115200,
  platformOptions: {
    vmin: 100,
    vtime: 0
  }
});

rs.on('open', function () {
  console.log("SerialPort opened");
});

var bytes = 0,
  ticks = 0,
  state = '0';

rs.on('data', function (data) {
});

test-fs.js

'use strict';

//var port = '/dev/tty.usbserial-A101DMMJ';
var port = '/dev/ttyATH0';

var SerialPort = require("serialport").SerialPort,
  net = require("net"),
  fs = require('fs');

fs.open(port, 'r', function (err, fd) {
  console.log('port opened! ' + err);

  var buffer = new Buffer(256),
    read;

  function readCb(err, bytesRead, buffer) {
    console.log(bytesRead);
    process.nextTick(read); // continue reading
  }

  read = function () {
    fs.read(fd, buffer, 0, buffer.length, null, readCb);
  };

  read();

});

[JohannesRudolph]

Thanks for merging #404 - one question though, have you figured out the reason for the difference between fs.read and reading through node-serialport?

I see that there's quite a bit of "smart" buffering going on in node-serialport, and to me it seems that in my case it works better to just use node-serialport for configuring the serialport and then reading from it using fs.

[leearmstrong]

Do you know if any progress was made with this?

[JohannesRudolph]

@leeus using vmin > 0 improves performance a lot by fixing a bottleneck in libuv (that's what landed in #404). Besides that, the bottleneck in node-serialport read still persists and so I'm using a combination of node-serialport and fs.read (well actually I've ditched node-serialport alltogether and use the stty tool to set parameters and then fs.read but that's just to save disk space and dependencies).

[leearmstrong]

Ah ok, I will make sure I update my clients to that then.

Interesting you ditched serial-port, I hadn't thought of doing it like that!

[0x80]

I think I might have ran into a similar problem where reading from the serialport at 115200 is showing high cpu load on a Mac (130% in activity monitor on latest MBP), but only when embedded in an Electron app. Running the same serialport code with just iojs showed 2% cpu. The current Electron shell (v28) uses iojs v2.2.1 and that's also the version I tested with.

Any idea how serialport could behave differently in combination with Electron?

[gregfriedland]

@JohannesRudolph I've been having similar problems getting 100% cpu usage with node-serialport, except I'm doing only writing in my case. (On a RaspberyPi 2 connecting to a Teensy 3.1). Could you share how you configured the port with stty so that you could use fs? It sounds like you were able to configure the device with node-serialport then use fs on it; how did you get that working? I can't find anything in the docs about how to get the fd from node-serialport to use in fs.

Thanks.

[JohannesRudolph]

@gregfriedland I'm using child_process to to invoke stty -Fand pass it a hex version of the settings, see the manpage of stty for details. After that I just do fs.open('/dev/ttyXX', 'w', function (err, fd) {... to get a file handle. No node-serialport involved.

[farfromrefug]

Any news on this? I am facing this issue when sending big data over serialport

[reconbot]

@farfromrefug nope, no news on this. We've cleaned up a few bugs that would cause high cpu usage since this was last updated but we haven't gone after performance yet. What platform are you running serialport on?

[farfromrefug]

@reconbot I am running serialport on 2 platforms to create a communication channel:

• rPi 2 model B
• OSX Yosemite (windows to come) The communication is mode through the USB control cable connected on the rPI GPIO (baudrate 115200)

[reconbot]

@farfromrefug #808 might help reduce cpu usage with writing

[reconbot]

I'd love if someone gave 5.0.0-beta3 a try, this should be greatly improved.

[farfromrefug]

@reconbot sorry for the very late answer! First https://github.com/EmergingTechnologyAdvisors/node-serialport/pull/808 did not help. I am using 4.0.7 and still seeing the issue. I actually created a second issue because it gives different details. I actually think that sending evens for every 1 or 2 bytes might be the reason for the high CPU usage.

Also about 5.0.0.beta3. I gave it a quick run but serialport was crashing too often (on both sides) so i had to switch back to 4.0.7 because i was in production. So i will try and give it another run

[reconbot]

Crash reports would be helpful too

On Tue, Apr 4, 2017, 9:04 AM Martin Guillon notifications@github.com wrote:

@reconbot https://github.com/reconbot sorry for the very late answer! First #808 https://github.com/EmergingTechnologyAdvisors/node-serialport/pull/808 did not help. I am using 4.0.7 and still seeing the issue. I actually created a second issue https://github.com/EmergingTechnologyAdvisors/node-serialport/issues/1128 because it gives different details. I actually think that sending evens for every 1 or 2 bytes might be the reason for the high CPU usage.

Also about 5.0.0.beta3. I gave it a quick run but serialport was crashing too often (on both sides) so i had to switch back to 4.0.7 because i was in production. So i will try and give it another run

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/EmergingTechnologyAdvisors/node-serialport/issues/402#issuecomment-291492854, or mute the thread https://github.com/notifications/unsubscribe-auth/AABlbmOwDajjNcMXtk8l7YR7eM6L_9KOks5rsj-8gaJpZM4CyaNo .

[farfromrefug]

@reconbot I will ! But i run serialport through electron and the crash report was not helping at all!

[reconbot]

5.0.0-Beta5 is now out with now even less code in the read and write paths. Hopefully it's a little more stable for you.

I'm going to close this issue due to it's age, but if you'd like to continue with it feel free to comment and we'll reopen.