[linux] Big cpu load (>10%) for reading on a serial port

[nouknouk]

Reopening issue https://github.com/serialport/node-serialport/issues/1590#issue-337506940 because things have not evolved with more recent version of serialport (7.1.x)

Maybe this is related to blocking IO when reading on serial port ; is it similar to issue https://github.com/serialport/node-serialport/issues/1221 , but for Linux system ?

config:

Software config:

• SerialPort Version: 7.1.5
• NodeJS Version: 12.4.0
• Operating System: Debian 64 bits Linux domo 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1+deb9u4 (2019-07-19) x86_64 GNU/Linux

Hardware config:

• Intel(R) Atom(TM) x5-Z8350 (cf. Z83II boxes sold around 80€ on Amazon, Gearbest, ...)
• One USB hub + several USB devices plugged on it (zwave key, zigbee key, arduino, APC UPS, ...)

lsusb

Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub Bus 001 Device 008: ID 1a86:7523 QinHeng Electronics HL-340 USB-Serial adapter Bus 001 Device 007: ID 0658:0200 Sigma Designs, Inc. Bus 001 Device 005: ID 05e3:0608 Genesys Logic, Inc. Hub Bus 001 Device 004: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC Bus 001 Device 006: ID 051d:0002 American Power Conversion Uninterruptible Power Supply Bus 001 Device 003: ID 067b:2303 Prolific Technology, Inc. PL2303 Serial Port Bus 001 Device 002: ID 05e3:0608 Genesys Logic, Inc. Hub Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

the problem raises with device 0403:6001, which is a (french) power consumption data gatherer, called 'module TELEINFO USB', from company GCE electronics ; it's basically a FTDI serial to USB converter at 1200 bauds, nothing more.

Summary of Problem

Big cpu load (>10%) for simply reading a serial port, @1200bauds, which sends something like 153 bytes every second ;

Steps and Code to Reproduce the Issue

I made a sample app, which lists the ports available, connect to the right one (according to pID & vID) and logs data received I monitor the cpu load with htop, filtering only node instances

  const SerialPort = require('serialport');
  const Delimiter = require('@serialport/parser-delimiter');

  let hardwarePath = '';

  SerialPort.list((err, list) => {
    if (err) throw new Error('error while attempting to retrieve the list of USB devices: '+err);

    list.forEach((dev) => {
      if (dev.vendorId === '0403' && dev.productId === '6001' && dev.manufacturer === 'FTDI') {
        console.log("found port "+JSON.stringify(dev));
        hardwarePath = dev.comName;
      }
    });

    if (hardwarePath) {
     console.log("connecting to (guessed) serial port '"+hardwarePath+"'...");

     var port = new SerialPort(hardwarePath, {
       baudRate: 1200,
       dataBits: 7,
       parity: 'even',
       stopBits: 1,
     });
     let parser = port.pipe(new Delimiter({ delimiter: [13,3,2,10] }));

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

     parser.on('data', function(data) {
       console.log( '['+(new Date())+'] serial port data: ', JSON.stringify(data.toString('utf8')) );
      });

     port.on('error', function(err) {
        console.log('serial port error.');
      });
     port.on('close', function() {
        console.log('serial port closed.');
      });
    }
    else {
      console.error("no suitable port found. Stopping.");
    }
});

the result in htop:

It shows that 12% of the CPU is used simply to read the frames from the serial port, whereas a cat /dev/ttyUSB0 consumes far less than 1% of CPU.

notes:

• the byte flow sent by the USB device is spread over the time (I can see progressive output when doing a cat /dev/ttyUSB0), but given the delimiter defined, it corresponds to approximatively one 'frame' every 1-2 seconds (cf. timestamps of logs in screenshot).

[HipsterBrown]

@nouknouk Do you have an expected range for CPU usage for this program? What kind of levels do you usually see for Node programs?

This could be due to the child process spawned to get the list of ports on linux. Could you see if the udevadm process is still running in the background while your program is running? Reads for unix systems are async, so they shouldn't be blocking.

[nouknouk]

hi @HipsterBrown

first, thanks for your answer and ideas.

• I removed the call to SerialPort.list, and hardcoded the port in my sample above ; no change.

• sudo ps -e | grep udevadm returns no udevadm process running (before, while & after running the sample).

• I expect a CPU range in the same scale as the one I get when I do a cat /dev/ttyUSB0, which is around 0.7% CPU.

• I did a second attempt, with a cat /dev/ttyUSB0 embedded in a node app ; it gives me something like 3-4% of CPU consumption.

const spawn =  require('child_process').spawn;
const child = spawn('cat', ['/dev/ttyUSB1']);
let buffer = '';
child.stdout.on('data', (data) => {
  buffer += data.toString();
  if (buffer.length > 100) {
    console.log(buffer);
    buffer = '';
  }
});

[HipsterBrown]

I did a second attempt, with a cat /dev/ttyUSB0 embedded in a node app ; it gives me something like 3-4% of CPU consumption.

Thanks for testing. I think your second attempt shows the base performance of using Node.js for some native tasks. cat presumably runs without an event loop and a runtime, like V8, so having it as a baseline for your program's performance is not exactly an apples to apples comparison.

Serialport is providing a nicer, high-level API over serial communication, which can come with a slight compromise in performance as the tradeoff.

[reconbot]

We use fs.read under the hood for linux reading, it doesn't get much more performant than that, however unlike cat we don't tie up a thread waiting for IO we use uv_poll_t to let us know when data is available. What we have in linux is what we moved windows to.

I'm positive there are some areas ripe for performance gains, I couldn't tell you where they are off hand. But if you discover any suggestions I'm for it.

[nouknouk]

ok, thanks for your answer. That's a bit pity through, that 10% of a (low end but) recent CPU gets eaten by such basic stuff.

Having 3 of them for a simple home automation system (the one above, one for zwave, another one for zigbee), this makes huge CPU consumption for something as simple as reading on serial ports.

Whatever, I assume this is not a 'bug', more some place where there's space for improvement ; therefore I'm closing this issue.

Thanks again for your ansewers & advices.