Understanding "weird" CPU behavior

[Adam]

Hi,

I've encountered a CPU issue which is somewhat of a puzzler for me.

Here's a description of what I'm doing: While investigating why an application written for Node.js was consuming what seemed to us as unreasonable amounts of CPU I ended up discovering that most of the CPU usage is actually attributed to framework we're using - Express.
I've validated this by comparing two "Hello World" style applications, both in single process mode and when using clustering.
I've implemented this super simple application using vanilla Node and then again using express:

Express version:

var express = require('express');
var app = express();

let userCount = 0;
app.get('/', function (req, res) {
  userCount++;
  const hello = {msg: "Hello world", userCount: userCount};
  res.send(JSON.stringify(hello));
});

app.listen(3000, function () {
  console.log('Example app listening on port 3000!');
});

Plain Node version

var http = require('http');

let userCount = 0;
var server = http.createServer(function (request, response) {
    userCount++;
    response.writeHead(200, {"Content-Type": "application/json"});
    const hello = {msg: "Hello world", userCount: userCount};
    response.end(JSON.stringify(hello));
});

server.listen(3000);
console.log("Server running at http://127.0.0.1:3000/");

I've then used wrk2 from a load generator machine (c4.large - 2 CPUs) to send a constant load (2k reqs/sec) to the machine (another c4.large) running each of these 4 setups.
I was expecting to see higher CPU with express (after all it does more) and I was expecting the clustered versions to use somewhat more CPU than the single process versions.
What I actually saw was that indeed the express version uses more CPU than the plain Node version, but while the extra total CPU used when putting the plain Node version in a cluster was a bit higher, the same test for the Express version yielding MUCH more CPU.

Here are the grand totals in all cases this includes both CPUs:

• single process - plain Node version - total 12.95%
• 2 processes using Node's cluster module - plain Node version - total 14.52%
• single process - Express version - total 19.05%
• 2 processes using Node's cluster module - Express version - total 30.66%

So, the results for the plain Node version are consistent with what I was expecting, but the results for the Express version are not.
As an initial step, I'd like to understand why does putting the same code inside a cluster perform so much worse when using express.
So I'm wondering regarding two things:

1. Are my assumption even correct? Perhaps with increased processing it IS actually expected to see such deterioration when moving from single to clustered?
   
2. If my assumption is correct, which tools (if any...) can I use to diagnose this so I'll know what to look for when I dive into the code. My initial intuition was increased context switches, but looking at vmstat output I could not find proof for that.
   

[Richard Warburton]

Hi,

Execution profilers are designed to tell you what part of your code is using up CPU time. I don't regularly touch Javascript myself, but the V8 Javascript runtime contains a builtin sampling profiler which can be run from node so that seems like a good place to start.

--
You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsub...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

regards,

  Richard Warburton

  http://insightfullogic.com

  @RichardWarburto

[Suresh Khemka]

Hi,

I have not used it myself but few of my team members working on node usually rely on Perf and flamegraphs for debugging similar issues.

http://www.brendangregg.com/flamegraphs.html

To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

regards,

  Richard Warburton

  http://insightfullogic.com

  @RichardWarburto

--
You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsub...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Regards
Suresh Kumar Khemka
+91 9741600488(M)
``Hard work never killed anybody...but why take chances?''     - Anonymous

[אדם חונן‎]

Yes, of course.

What I've been doing with the profiler (which BTW, is a sampling profiler...) is this: run in both modes - single process and cluster for the same duration of time, then compare the absolute execution time.

The thing is, the profiler will show you where the CPU is spent, but what I want to understand is why, when using the express version, suddenly the effect of splitting the traffic to two seems to use that much more CPU in relation to when running in a single process.
You see, when using the cluster module you have 3 processes: 1 master and 2 workers. The master routes requests in a round robin manner to the 2 workers.
Without Express, you see the master taking close to 0 CPU and the work being roughly routed to the two workers.
The result is a slightly higher CPU usage with each worker doing pretty much what previously a single process did (only half the requests).

When using express, the master process acts the same way - express is not used on that process. Not even loaded to memory.
So OK, with Express there's a certain extra XX% of work that's being done because it also handles HTTP routes, does more elaborate request parsing and what not.
For the sake of example, let's say it does +47% work as it happened when I measured it on my machines.
I still expect that when moving to the clustered setup, although this extra 47% will apply to each process, the grand total of CPU will be roughly the same (or actually slightly larger) than when running in a single process - just like it was when not using Express.
After all, the Express code is agnostic to running in a single process, or via the cluster module.

So since the actual result is that the difference goes up to 111%, I was thinking that there's something else going on here as well and that the processes are somehow interfering with one another somehow  - directly or indirectly.
I'm not sure a profiler is the right tool to check that and hence my question - what is.

To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

regards,

  Richard Warburton

  http://insightfullogic.com

  @RichardWarburto

--
You received this message because you are subscribed to a topic in the Google Groups "mechanical-sympathy" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/mechanical-sympathy/_R1dyjgMD1Q/unsubscribe.
To unsubscribe from this group and all its topics, send an email to mechanical-sympathy+unsub...@googlegroups.com.

[Alen Vrečko]

Did you profile "per process" or "per OS"? Flame graphs are awesome.
Compare the flame graph of Express non-clustered with Express
clustered. I'd be surprised if nothing pops-up.

>>> email to mechanical-symp...@googlegroups.com.

>>> For more options, visit https://groups.google.com/d/optout.
>>
>>
>>
>>
>> --
>> regards,
>>
>> Richard Warburton
>>
>> http://insightfullogic.com
>> @RichardWarburto
>>
>> --
>> You received this message because you are subscribed to a topic in the
>> Google Groups "mechanical-sympathy" group.
>> To unsubscribe from this topic, visit
>> https://groups.google.com/d/topic/mechanical-sympathy/_R1dyjgMD1Q/unsubscribe.
>> To unsubscribe from this group and all its topics, send an email to

>> mechanical-symp...@googlegroups.com.

>> For more options, visit https://groups.google.com/d/optout.
>
>
> --

> You received this message because you are subscribed to the Google Groups
> "mechanical-sympathy" group.
> To unsubscribe from this group and stop receiving emails from it, send an

> email to mechanical-symp...@googlegroups.com.