worker: add eventLoopUtilization() #35664

trevnorris · 2020-10-15T23:15:59Z

NOTE: While this is working as it should, I feel the implementation may be a bit clunky. Specifically the one TODO about thread-safe access to a performance mark. Looking for feedback on how this could be improved.

worker: add eventLoopUtilization()

Allow calling eventLoopUtilization() directly on a worker thread:

const worker = new Worker('./foo.js');
const elu = worker.performance.eventLoopUtilization();
setTimeout(() => {
  worker.performance.eventLoopUtilization(elu);
}, 10);

Add a new performance object on the Worker instance that will hopefully
one day hold all the other performance metrics, such as nodeTiming.

Include benchmarks and tests.

Also include a commit that improves tests for perf_hooks.performance.eventLoopUtilization().

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

juanarbol

LGTM

jasnell · 2020-10-15T23:59:30Z

src/node_worker.cc

+    return args.GetReturnValue().Set(-1);
+
+  // TODO(trevnorris): This isn't technically thread safe.
+  double loop_start_time = w->env_->performance_state()->milestones[


The key question here then would be if the loop start milestone is guaranteed to be set before user code is permitted to call LoopStartTime. I suspect that it's not. Curious what @addaleax thinks here.

I've checked and it's not guaranteed. The reason this (probably) works is because it's only doing a read, and the value is only written to once. So if the state hasn't synchronized it'll return {active: 0, idle: 0, utilization: 0}.

The reason this (probably) works is because it's only doing a read, and the value is only written to once. So if the state hasn't synchronized it'll return {active: 0, idle: 0, utilization: 0}.

It’s not necessarily that easy – we should not assume that 64-bit reads & writes are atomic on every platform, I think.

The easiest way to work around this would probably be to only allow calling this function if the 'online' event has been received on the Worker instance, and if not, skipping this call into C++. We could then assert here that loop_start_time > 0.

@addaleax 64-bit reads/writes are always atomic on 64-bit systems if the memory is aligned. So, since we support 32-bit Windows builds, I guess this isn't solved so easily. :-(

@trevnorris That’s true for x64, but we’re also supporting arm and ppc :)

jasnell · 2020-10-16T00:00:39Z

Looks good but let's work through the possible threadsafety issue on the performance mark before sign off

juanarbol · 2020-10-16T00:17:30Z

I'm agree with @jasnell, sorry about the rush, haha

src/node_worker.cc

lib/internal/worker.js

addaleax · 2020-10-16T08:40:56Z

src/node_worker.cc

+    return args.GetReturnValue().Set(-1);
+
+  // TODO(trevnorris): This isn't technically thread safe.
+  double loop_start_time = w->env_->performance_state()->milestones[


The reason this (probably) works is because it's only doing a read, and the value is only written to once. So if the state hasn't synchronized it'll return {active: 0, idle: 0, utilization: 0}.

It’s not necessarily that easy – we should not assume that 64-bit reads & writes are atomic on every platform, I think.

The easiest way to work around this would probably be to only allow calling this function if the 'online' event has been received on the Worker instance, and if not, skipping this call into C++. We could then assert here that loop_start_time > 0.

trevnorris · 2020-10-16T18:51:51Z

@addaleax Thanks for the review. I've made fixes for everything, including only allowing to call LoopStartTime after the 'online' event.

edit: adding the is online check doesn't allow the benchmark to run. working on this.

trevnorris · 2020-10-16T20:23:15Z

@addaleax Fix the benchmark issue. Which made me realize that because reading the ELU of a worker can't be done until after the 'online' event, it now required the event loop to iterate at least once before it can be read.

This isn't optimal, but I can't think of a better solution for now. In the future I wanted to make reading/writing to all the milestones atomic so we could add worker.performance.nodeTiming as well. If that ever happens, we can remove the current limitation.

addaleax · 2020-10-17T17:05:49Z

Which made me realize that because reading the ELU of a worker can't be done until after the 'online' event, it now required the event loop to iterate at least once before it can be read.

I think the current approach of returning an object with 0 values is just fine.

In the future I wanted to make reading/writing to all the milestones atomic so we could add worker.performance.nodeTiming as well.

Keep in mind that even if reading a single value might be atomic, reading the entire group of timing values would not be.

addaleax · 2020-10-17T17:07:22Z

@nodejs/workers

nodejs-github-bot · 2020-10-17T17:15:33Z

CI: https://ci.nodejs.org/job/node-test-pull-request/33692/

benjamingr · 2020-10-18T07:24:03Z

doc/api/worker_threads.md

+values for the worker instance.
+
+Currently the event loop utilization of a worker instance can only be retrieved
+after the [`'online'` event][] event has fired.


Add note about what happens if you call it before online has fired?

Suggested change

after the [`'online'` event][] event has fired.

after the [`'online'` event][] is emitted.

benjamingr · 2020-10-18T07:25:06Z

lib/internal/worker.js

@@ -223,6 +227,12 @@ class Worker extends EventEmitter {
        null,
      hasStdin: !!options.stdin
    }, transferList);
+    // Use this to cache the Worker's loopStart value once available.
+    this[kLoopStartTime] = -1;


Put the -1 in a const?

@benjamingr Sorry, I don't follow what you mean.

benjamingr · 2020-10-18T07:26:54Z

lib/internal/worker.js

@@ -415,6 +426,50 @@ function makeResourceLimits(float64arr) {
  };
 }

+function eventLoopUtilization(util1, util2) {
+  // TODO(trevnorris): Works to solve the thread-safe read/write issue of


Would it make sense for the API instead to be emitted on online so:

The worker emits online with an "stats" argument

The stats argument has this eventLoopUtilization method the user can call

That would make it impossible to use this API incorrectly and remove a bit of the weirdness.

That seems like it makes accessing the API more difficult, with little benefit…

@addaleax
Well, the benefit is that it would be impossible to misuse the API. Currently this API has a (relatively small) footgun if you call eventLoopUtilization before online is fired. That eliminates the footgun.

Note that the API isn't really that bad:

const worker = new Worker(...); const controller = await once(worker, 'online'); console.log(controller.eventLoopUtilization()); // same thing as currently on worker now

@benjamingr I think my disagreement is more about whether this is a footgun or not :) If you call it before the 'online' event, you don’t get inaccurate data, you get no ELU data – which is accurate, because (up to race conditions) there actually is no ELU data available.

If you think the distinction between "no data" and "0 data" here isn't important - I will concede.

@benjamingr I plan on figuring out a way to remove the limitation of not being able to query the ELU until the 'online' event has been emitted.

benjamingr · 2020-10-18T07:27:31Z

lib/internal/worker.js

+  // has had a chance to turn. So it will be impossible to read the ELU of
+  // a worker thread immediately after it's been created.
+  if (!this[kIsOnline]) {
+    return { idle: 0, active: 0, utilization: 0 };


If we keep this API, I really prefer it if we didn't return 0s to indicate "not yet online" here and instead throw an error. I can see users running into footguns here.

This currently agrees with the behavior on the main thread. I think throwing an error would be the (way) more unexpected result.

benjamingr · 2020-10-18T07:28:10Z

lib/internal/worker.js

+  }
+
+  // Cache loopStart, since it's only written to once.
+  if (this[kLoopStartTime] <= 0) {


=== -1 (rather than <=0) ? (also, const?)

benjamingr · 2020-10-18T12:16:15Z

Also, I did not actually check out the branch and play with it so I didn't LGTM as this already has enough approvals - but if that would help/is needed here I am happy to do that.

To be clear (eventhough thankfully our process doesn't require this anymore): none of my comments are blocking and I am +1 on these changes in general.

Allow calling eventLoopUtilization() directly on a worker thread: const worker = new Worker('./foo.js'); const elu = worker.performance.eventLoopUtilization(); setTimeout(() => { worker.performance.eventLoopUtilization(elu); }, 10); Add a new performance object on the Worker instance that will hopefully one day hold all the other performance metrics, such as nodeTiming. Include benchmarks and tests. PR-URL: nodejs#35664 Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Gerhard Stöbich <deb2001-github@yahoo.de> Reviewed-By: James M Snell <jasnell@gmail.com> Backport-PR-URL: nodejs#35664

Allow calling eventLoopUtilization() directly on a worker thread: const worker = new Worker('./foo.js'); const elu = worker.performance.eventLoopUtilization(); setTimeout(() => { worker.performance.eventLoopUtilization(elu); }, 10); Add a new performance object on the Worker instance that will hopefully one day hold all the other performance metrics, such as nodeTiming. Include benchmarks and tests. PR-URL: nodejs#35664 Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Gerhard Stöbich <deb2001-github@yahoo.de> Reviewed-By: James M Snell <jasnell@gmail.com> Backport-PR-URL: nodejs#37165

The active worker check compared the time from sending message till response arrived from worker with the complete time the worker was running till it responses to the spin request. If sending back the message is slow for some reason the test fails. Adapt the test to compare the time seen inside the worker with the time read from main thread. PR-URL: nodejs#35891 Fixes: nodejs#35844 Refs: nodejs#35886 Refs: nodejs#35664 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Rich Trott <rtrott@gmail.com> Backport-PR-URL: nodejs#37165

The active worker check compared the time from sending message till response arrived from worker with the complete time the worker was running till it responses to the spin request. If sending back the message is slow for some reason the test fails. Adapt the test to compare the time seen inside the worker with the time read from main thread. PR-URL: nodejs#35891 Fixes: nodejs#35844 Refs: nodejs#35886 Refs: nodejs#35664 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Rich Trott <rtrott@gmail.com> Backport-PR-URL: nodejs#37163

Allow calling eventLoopUtilization() directly on a worker thread: const worker = new Worker('./foo.js'); const elu = worker.performance.eventLoopUtilization(); setTimeout(() => { worker.performance.eventLoopUtilization(elu); }, 10); Add a new performance object on the Worker instance that will hopefully one day hold all the other performance metrics, such as nodeTiming. Include benchmarks and tests. PR-URL: nodejs#35664 Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Gerhard Stöbich <deb2001-github@yahoo.de> Reviewed-By: James M Snell <jasnell@gmail.com> Backport-PR-URL: nodejs#37165

The active worker check compared the time from sending message till response arrived from worker with the complete time the worker was running till it responses to the spin request. If sending back the message is slow for some reason the test fails. Adapt the test to compare the time seen inside the worker with the time read from main thread. PR-URL: nodejs#35891 Fixes: nodejs#35844 Refs: nodejs#35886 Refs: nodejs#35664 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Rich Trott <rtrott@gmail.com> Backport-PR-URL: nodejs#37165

Allow calling eventLoopUtilization() directly on a worker thread: const worker = new Worker('./foo.js'); const elu = worker.performance.eventLoopUtilization(); setTimeout(() => { worker.performance.eventLoopUtilization(elu); }, 10); Add a new performance object on the Worker instance that will hopefully one day hold all the other performance metrics, such as nodeTiming. Include benchmarks and tests. PR-URL: #35664 Backport-PR-URL: #37163 Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Gerhard Stöbich <deb2001-github@yahoo.de> Reviewed-By: James M Snell <jasnell@gmail.com>

The active worker check compared the time from sending message till response arrived from worker with the complete time the worker was running till it responses to the spin request. If sending back the message is slow for some reason the test fails. Adapt the test to compare the time seen inside the worker with the time read from main thread. PR-URL: #35891 Fixes: #35844 Refs: #35886 Refs: #35664 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Rich Trott <rtrott@gmail.com> Backport-PR-URL: #37163