os.cpus() and times

[// ravi]

Hello all,

I posted this question on node-forward/help on Gitter, so apologies if you are seeing this again.

I am stumped by what must clearly be a misreading on my part. Node 0.10 docs say that each element of os.cpus() contains information about each CPU/core. This information includes "the number of milliseconds the CPU/core spent in: user, nice, sys, idle, and irq” (the docs do not say milliseconds of what, but I assume it means milliseconds since the system was last started). Note that this used to be, in v0.8 (and I assume before), reported in CPU ticks, but seems to have switched to milliseconds for v0.10.

Now for the puzzle: say I do this:

console.log(os.cpus()[0].times.idle);
setTimeout(function() { console.log(os.cpus()[0].times.idle); }, 2000);

The output I see is:

39035126800
39035144500

Assuming that ordering of CPUs/cores is consistent in the array returned by os.cpus(), it’s not clear how to square the above with the docs. The difference between the times reported is 17700ms i.e., CPU 0 was idle for 17 seconds in the 2 seconds between the two calls!

I guess I am doing something trivially wrong in the above, but what is it?

Any help appreciated!

—ravi

[// ravi]

On Dec 7, 2014, at 11:06 PM, // ravi <ravi-...@g8o.net> wrote:
>
>
> I am stumped by what must clearly be a misreading on my part. Node 0.10 docs say that each element of os.cpus() contains information about each CPU/core. This information includes "the number of milliseconds the CPU/core spent in: user, nice, sys, idle, and irq” (the docs do not say milliseconds of what, but I assume it means milliseconds since the system was last started). Note that this used to be, in v0.8 (and I assume before), reported in CPU ticks, but seems to have switched to milliseconds for v0.10.
>
> Now for the puzzle: say I do this:
>
> console.log(os.cpus()[0].times.idle);
> setTimeout(function() { console.log(os.cpus()[0].times.idle); }, 2000);
>
> The output I see is:
>
> 39035126800
> 39035144500
>
> Assuming that ordering of CPUs/cores is consistent in the array returned by os.cpus(), it’s not clear how to square the above with the docs. The difference between the times reported is 17700ms i.e., CPU 0 was idle for 17 seconds in the 2 seconds between the two calls!
>

One thing to consider is if os.cpus() returns CPU usage information from /proc/stats. If so, two things could affect the above (more likely the second):

(1) the first line of /proc/stats in GNU/Linux reports the totals across CPUs.
(2) these numbers seem to be in “jiffies” or 1/100th of a second (USER_HZ).

Time to start digging into the ‘os’ module sources, I guess, though I think Ockham’s Razor continues to point at me.

—ravi

[Christopher Rust]

I can't comment on how cpu idle time is calculated or if the cpus() array is consistently ordered but I can point out that setTimeout is not expected to be perfectly accurate.

From the <a href="http://nodejs.org/api/timers.html">documentation</a>:

"It is important to note that your callback will probably not be called in exactly delay milliseconds - Node.js makes no guarantees about the exact timing of when the callback will fire, nor of the ordering things will fire in. The callback will be called as close as possible to the time specified."

Even clearer might be to say: "The callback will be called as soon as possible after the specified time has passed."

Still, 17 seconds seems like a lot. Are you saying that's 17 seconds real time as well?

Responding from mobile so forgive any errors,

Chris (raptastics)

--
Job board: http://jobs.nodejs.org/
New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
---
You received this message because you are subscribed to the Google Groups "nodejs" group.
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+un...@googlegroups.com.
To post to this group, send email to nod...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/CAEEC821-242A-4C65-8F07-C6B751A1B07E%40g8o.net.
For more options, visit https://groups.google.com/d/optout.

[// ravi]

Digging done :-). More info here: https://github.com/joyent/node/issues/8835. It’s possible this will need a fix in the ‘os’ module. I have suggested the outline of such a fix, if needed, in the Issue.

—ravi

[// ravi]

> On Dec 8, 2014, at 12:43 AM, Christopher Rust <cru...@gmail.com> wrote:
>
> I can't comment on how cpu idle time is calculated or if the cpus() array is consistently ordered but I can point out that setTimeout is not expected to be perfectly accurate.
>

> <…>

> Still, 17 seconds seems like a lot. Are you saying that's 17 seconds real time as well?
>

It’s not 17 seconds in real time… it’s two seconds :-). Hence my puzzlement. We can add some detail to bring this out:

setInterval
(
function()
{
console.log("Time is", Date.now(),
"and idle time is", os.cpus()[0].times.idle);
},
2000
);

And the output is:

Time is 1418051000768 and idle time is 39311772900
Time is 1418051002770 and idle time is 39311790100
Time is 1418051004772 and idle time is 39311808000
Time is 1418051006774 and idle time is 39311824600
…

The between intervals is fairly consistent and about 2000ms as expected. The idle times for the corresponding intervals are approx 17s, 18s, 16.5s! (if laziness is a virtue of a programmer, I think I might have stumbled upon the Holy Grail: the ability to squeeze more idle time than are available on the clock!).

Closer inspection reveals what might be the issue: if you take the idle time reported to be not in ms, but 100*ms (where 100 = GNU/Linux clock ticks per sec), then it starts to seem right. Throwing away the *100, the idle times become:

393117729
393117901
393118080
393118246

Or approx 2s, 1s, 2s each.

What does continue to puzzle me is that if the ‘os’ module is adding on a extra *100 to the time, then how is it reporting data at this level of granularity i.e., there should be a lot more trailing zeroes, since the OS does not report this data at ms granularity.

—ravi

[// ravi]

On Dec 8, 2014, at 10:17 AM, // ravi <ravi-...@g8o.net> wrote:
>
> Closer inspection reveals what might be the issue: if you take the idle time reported to be not in ms, but 100*ms (where 100 = GNU/Linux clock ticks per sec), then it starts to seem right. Throwing away the *100, the idle times become:
>
> 393117729
> 393117901
> 393118080
> 393118246
>
> Or approx 2s, 1s, 2s each.

The above is a bit wrong. To account for the clock ticks per second, I cannot just throw away the *100, I have to throw away ms_per_sec/clock_ticks_per_sec = 1000/100 = 10. Which gives me the times, in ms:

3931177290
3931179010
3931180800
3931182460

Or idle durations of approx 1.7s, 1.8s, 1.6s.

The corrected math above also clears away my earlier confusion about the higher than expected granularity of the times.That is no longer the case. The times above have a granularity of 1/100th of a second (the last digit is always zero in the ms), which is exactly the granularity that the OS reports at.

—ravi