util: improve util inspect performance #22503

BridgeAR · 2018-08-24T13:42:07Z

This significantly improves the inspection performance for all array
types. From now on only the visible elements cause work instead of
having to process all array keys no matter how many entries are
visible. So the complexity for (typed) arrays is reduced from
O(n + m) to O(m), while n is the number of keys and m is the
number of visible entries. m is set to 100 by default
(maxArrayLength).

This also moves some code out of the main function to reduce the
overall function complexity.

It also adds a specific boxed primitives c++ function to reduce the
boundary crossing for the average use case (boxed primitives are rare).

I also reduced the runtime for the util benchmarks as they were significantly
to high and removed some obsolete options.

Intermediate benchmark results:

 util/inspect-array.js type='denseArray_showHidden' len=100 n=500             ***     16.58 %       ±2.32%   ±3.09%   ±4.02%
 util/inspect-array.js type='denseArray_showHidden' len=100000 n=500          ***  35312.58 %     ±352.42% ±474.97% ±630.57%
 util/inspect-array.js type='denseArray' len=100 n=500                        ***     11.41 %       ±2.29%   ±3.04%   ±3.96%
 util/inspect-array.js type='denseArray' len=100000 n=500                     ***  19361.00 %     ±243.13% ±327.68% ±435.02%
 util/inspect-array.js type='mixedArray' len=100 n=500                        ***     16.69 %       ±2.88%   ±3.83%   ±4.98%
 util/inspect-array.js type='mixedArray' len=100000 n=500                     ***      1.64 %       ±0.53%   ±0.70%   ±0.92%
 util/inspect-array.js type='sparseArray' len=100 n=500                       ***      3.62 %       ±1.40%   ±1.87%   ±2.45%
 util/inspect-array.js type='sparseArray' len=100000 n=500                             0.31 %       ±0.69%   ±0.92%   ±1.20%
 util/inspect-proxy.js n=20000                                                ***     -5.93 %       ±3.01%   ±4.01%   ±5.22%
 util/inspect.js option='none' method='Array' n=20000                         ***      6.69 %       ±0.92%   ±1.23%   ±1.60%
 util/inspect.js option='none' method='Date' n=20000                           **     -5.01 %       ±2.92%   ±3.90%   ±5.13%
 util/inspect.js option='none' method='Error' n=20000                         ***    -11.74 %       ±3.11%   ±4.16%   ±5.44%
 util/inspect.js option='none' method='Number' n=20000                        ***     19.64 %       ±2.57%   ±3.43%   ±4.49%
 util/inspect.js option='none' method='Object_deep_ln' n=20000                         0.61 %       ±1.80%   ±2.42%   ±3.18%
 util/inspect.js option='none' method='Object_empty' n=20000                  ***     -9.55 %       ±2.98%   ±3.99%   ±5.23%
 util/inspect.js option='none' method='Object' n=20000                                -0.94 %       ±1.80%   ±2.39%   ±3.12%
 util/inspect.js option='none' method='Set' n=20000                             *     -4.64 %       ±3.54%   ±4.72%   ±6.15%
 util/inspect.js option='none' method='String_boxed' n=20000                  ***    -11.52 %       ±1.96%   ±2.61%   ±3.40%
 util/inspect.js option='none' method='String_complex' n=20000                ***      7.97 %       ±2.29%   ±3.05%   ±3.97%
 util/inspect.js option='none' method='String' n=20000                        ***     15.03 %       ±3.54%   ±4.73%   ±6.19%
 util/inspect.js option='none' method='TypedArray_extra' n=20000              ***     39.86 %       ±2.39%   ±3.19%   ±4.16%
 util/inspect.js option='none' method='TypedArray' n=20000                    ***     31.53 %       ±3.66%   ±4.91%   ±6.47%
 util/inspect.js option='showHidden' method='Array' n=20000                   ***     23.30 %       ±3.02%   ±4.07%   ±5.39%
 util/inspect.js option='showHidden' method='Date' n=20000                     **     -3.12 %       ±1.92%   ±2.56%   ±3.34%
 util/inspect.js option='showHidden' method='Error' n=20000                           -2.64 %       ±3.82%   ±5.12%   ±6.74%
 util/inspect.js option='showHidden' method='Number' n=20000                  ***     15.16 %       ±2.83%   ±3.77%   ±4.90%
 util/inspect.js option='showHidden' method='Object_deep_ln' n=20000                  -0.62 %       ±1.68%   ±2.26%   ±2.98%
 util/inspect.js option='showHidden' method='Object_empty' n=20000            ***    -10.84 %       ±2.09%   ±2.80%   ±3.66%
 util/inspect.js option='showHidden' method='Object' n=20000                           0.08 %       ±1.86%   ±2.48%   ±3.23%
 util/inspect.js option='showHidden' method='Set' n=20000                             -2.69 %       ±3.61%   ±4.84%   ±6.36%
 util/inspect.js option='showHidden' method='String_boxed' n=20000            ***    -10.19 %       ±1.70%   ±2.26%   ±2.95%
 util/inspect.js option='showHidden' method='String_complex' n=20000          ***      6.34 %       ±2.57%   ±3.42%   ±4.45%
 util/inspect.js option='showHidden' method='String' n=20000                  ***      9.59 %       ±2.45%   ±3.27%   ±4.26%
 util/inspect.js option='showHidden' method='TypedArray_extra' n=20000        ***     60.41 %       ±2.94%   ±3.91%   ±5.08%
 util/inspect.js option='showHidden' method='TypedArray' n=20000              ***     75.31 %       ±1.55%   ±2.07%   ±2.71%

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

nodejs-github-bot · 2018-08-24T13:42:08Z

@BridgeAR build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/660/pipeline

BridgeAR · 2018-08-24T14:48:17Z

~~CI https://ci.nodejs.org/job/node-test-pull-request/16729/~~
CI https://ci.nodejs.org/job/node-test-pull-request/16730/
Benchmark https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/228/

mscdex · 2018-08-24T15:18:38Z

src/node_types.cc

@@ -51,6 +51,15 @@ static void IsAnyArrayBuffer(const FunctionCallbackInfo<Value>& args) {
    args[0]->IsArrayBuffer() || args[0]->IsSharedArrayBuffer());
 }

+static void IsBoxedPrimitive(const FunctionCallbackInfo<Value>& args) {


Would it be faster to do this in javascript somehow? For example: typeof arg === 'object' && arg !== null && arg.constructor === String ?

I did not test it but I would not want to use it as it's not a safe check. Someone could easily manipulate the constructor.

const s = new String('test') s.constructor = Number

Alright, how about:

if (typeof arg === 'object' && arg !== null && Object.prototype.toString.call(arg) === '[object String]')

? Object.prototype.toString could even be cached at startup in case someone overrides it later on.

The only issue would be symbols and big integers as they don't have constructors that return object types, but at least maybe we could speed up the other type checks if this js method ends up being faster or avoid crossing the C++<->js boundary entirely if we place the symbol and bigint checks last.

That is also not a safe check:

const a = new String('test') a[Symbol.toStringTag] = 'Foo' console.log(Object.prototype.toString.call(a)) // '[object Foo]'

I'll move the bigint check in the C++ function down and I'll see if I can work around the performance penalty. Do you expect a lot of people using boxed primitives? Because for all other cases there are now less calls to C++ than before.

Seems like the main regression came due to moving the functionality to an extra function. It's probably not inlined anymore as other code is hotter and the main function is already big. I moved it back in to address the performance regression.

jdalton · 2018-08-24T19:22:28Z

src/node_types.cc

+    args[0]->IsStringObject() ||
+    args[0]->IsSymbolObject());
+}
+


@BridgeAR 👆 Ideally this helper should have a JS form (that calls it) exposed on util.types like the other isNumberObject, etc.

That is automatically the case. But good that you bring it up! I'll move this to an individual commit that also adds documentation for the function.

refack · 2018-08-24T19:44:20Z

I -1 on this.
IMHO util.inspect is a cold path, and I would much rather stability and readability. Again IMHO this is not a place that is worth the churn:

mscdex · 2018-08-24T19:50:53Z

I'm not sure I'd call util.inspect a "cold path". I could see end users using it for logging purposes for example.

refack · 2018-08-24T20:06:40Z

I'm not sure I'd call util.inspect a "cold path". I could see end users using it for logging purposes for example.

Ok. But then I'd assume log appending will generate I/O that will shadow the CPU work by inspect. In anyway I'm not convinced even a 100% improvement here is worth the churn, and possible instability.
If we can find a real world workload that this change improves significantly, I'd be happy to change my mind.

jdalton · 2018-08-24T20:07:25Z

@refack

This is goodness for util.inspect which is used by the REPL and many console methods. And the helpers introduced in this PR can in turn be goodness for util.types (in a follow-up). @BridgeAR is heavily involved in making improvements to util.inspect. I'm in favor of more of these incremental improvements. Long term I'd like to see inspect moved to its own file or folder of files (it's got enough parts).

refack · 2018-08-24T20:40:14Z

This is goodness for util.inspect which is used by the REPL and many console methods. And the helpers introduced in this PR can in turn be goodness for util.types (in a follow-up).

Then this needs reframing. Call it util: refactor `util.inspect` and let's judge this on merits of readability and reusability.

jdalton · 2018-08-24T21:26:05Z

@refack The PR here doesn't appear to make things any harder to reason about, simplifies an expensive set of operations, and opens the possibility of carrying over useful helpers to util.types.

Would it help if this PR moved/saved any of the source refactoring and cleanup bits for another PR?

BridgeAR · 2018-08-25T12:14:31Z

@refack I actually tried to reduce the overall complexity while significantly improving the performance. util.inspect is used a ton and we ran into multiple issues because there is a performance overhead when inspecting bigger objects. Here are some issues and PRs that dealt with util.inspect overhead #19994 #19405 #17791 #6334.

@jdalton

Long term I'd like to see inspect moved to its own file or folder of files

Definitely! I want to do that as well.

BridgeAR · 2018-08-26T11:54:05Z

I just pushed two new commits: one to document the new function and one to address the boxed regression.

~~CI https://ci.nodejs.org/job/node-test-pull-request/16759/~~
CI https://ci.nodejs.org/job/node-test-pull-request/16771/

BridgeAR · 2018-08-26T11:54:53Z

@nodejs/util PTAL

targos · 2018-09-08T12:14:06Z

Should this be backported to v10.x-staging? If yes please follow the guide and raise a backport PR, if not let me know or add the dont-land-on label.

PR-URL: nodejs#22503 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: John-David Dalton <john.david.dalton@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

This significantly reduces the benchmark runtime. It removes to many variations that do not provide any benefit and reduces the iterations. PR-URL: nodejs#22503 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: John-David Dalton <john.david.dalton@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

This significantly improves the inspection performance for all array types. From now on only the visible elements cause work instead of having to process all array keys no matter how many entries are visible. This also moves some code out of the main function to reduce the overall function complexity. PR-URL: nodejs#22503 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: John-David Dalton <john.david.dalton@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

Backport-PR-URL: #23039 PR-URL: #22503 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: John-David Dalton <john.david.dalton@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

This significantly reduces the benchmark runtime. It removes to many variations that do not provide any benefit and reduces the iterations. Backport-PR-URL: #23039 PR-URL: #22503 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: John-David Dalton <john.david.dalton@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

This significantly improves the inspection performance for all array types. From now on only the visible elements cause work instead of having to process all array keys no matter how many entries are visible. This also moves some code out of the main function to reduce the overall function complexity. Backport-PR-URL: #23039 PR-URL: #22503 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: John-David Dalton <john.david.dalton@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. util Issues and PRs related to the built-in util module. labels Aug 24, 2018

BridgeAR force-pushed the improve-util-perf branch from acb806d to 2224329 Compare August 24, 2018 14:45

mscdex reviewed Aug 24, 2018

View reviewed changes

BridgeAR added the performance Issues and PRs related to the performance of Node.js. label Aug 24, 2018

jdalton reviewed Aug 24, 2018

View reviewed changes

BridgeAR requested review from addaleax and mscdex August 27, 2018 13:21

BridgeAR assigned mcollina, jasnell, benjamingr and devsnek and unassigned mcollina, jasnell, benjamingr and devsnek Aug 27, 2018

BridgeAR requested review from devsnek, benjamingr and jasnell August 27, 2018 13:22

targos mentioned this pull request Sep 15, 2018

[v10.x needs a backport] - util: improve util inspect performance #22872

Closed

targos added this to Backport requested in v10.x Sep 23, 2018

targos mentioned this pull request Sep 23, 2018

[v10.x] Backport util PRs #23039

Closed

targos added backported-to-v10.x and removed author ready PRs that have at least one approval, no pending requests for changes, and a CI started. backport-requested-v10.x labels Sep 24, 2018

targos moved this from Backport requested to Backported in v10.x Sep 24, 2018

targos mentioned this pull request Oct 7, 2018

Release proposal: v10.12.0 #23313

Merged

BridgeAR mentioned this pull request Dec 20, 2019

for ... of replacing for(;;) in library networking code? #31024

Closed

BridgeAR deleted the improve-util-perf branch January 20, 2020 11:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

util: improve util inspect performance #22503

util: improve util inspect performance #22503

BridgeAR commented Aug 24, 2018

nodejs-github-bot commented Aug 24, 2018

BridgeAR commented Aug 24, 2018 •

edited

Loading

mscdex Aug 24, 2018 •

edited

Loading

BridgeAR Aug 24, 2018 •

edited

Loading

mscdex Aug 24, 2018 •

edited

Loading

BridgeAR Aug 25, 2018 •

edited

Loading

BridgeAR Aug 26, 2018 •

edited

Loading

jdalton Aug 24, 2018

BridgeAR Aug 25, 2018

refack commented Aug 24, 2018

mscdex commented Aug 24, 2018

refack commented Aug 24, 2018

jdalton commented Aug 24, 2018

refack commented Aug 24, 2018

jdalton commented Aug 24, 2018 •

edited

Loading

BridgeAR commented Aug 25, 2018

BridgeAR commented Aug 26, 2018 •

edited

Loading

BridgeAR commented Aug 26, 2018

targos commented Sep 8, 2018

util: improve util inspect performance #22503

util: improve util inspect performance #22503

Conversation

BridgeAR commented Aug 24, 2018

Checklist

nodejs-github-bot commented Aug 24, 2018

BridgeAR commented Aug 24, 2018 • edited Loading

mscdex Aug 24, 2018 • edited Loading

Choose a reason for hiding this comment

BridgeAR Aug 24, 2018 • edited Loading

Choose a reason for hiding this comment

mscdex Aug 24, 2018 • edited Loading

Choose a reason for hiding this comment

BridgeAR Aug 25, 2018 • edited Loading

Choose a reason for hiding this comment

BridgeAR Aug 26, 2018 • edited Loading

Choose a reason for hiding this comment

jdalton Aug 24, 2018

Choose a reason for hiding this comment

BridgeAR Aug 25, 2018

Choose a reason for hiding this comment

refack commented Aug 24, 2018

mscdex commented Aug 24, 2018

refack commented Aug 24, 2018

jdalton commented Aug 24, 2018

refack commented Aug 24, 2018

jdalton commented Aug 24, 2018 • edited Loading

BridgeAR commented Aug 25, 2018

BridgeAR commented Aug 26, 2018 • edited Loading

BridgeAR commented Aug 26, 2018

targos commented Sep 8, 2018

BridgeAR commented Aug 24, 2018 •

edited

Loading

mscdex Aug 24, 2018 •

edited

Loading

BridgeAR Aug 24, 2018 •

edited

Loading

mscdex Aug 24, 2018 •

edited

Loading

BridgeAR Aug 25, 2018 •

edited

Loading

BridgeAR Aug 26, 2018 •

edited

Loading

jdalton commented Aug 24, 2018 •

edited

Loading

BridgeAR commented Aug 26, 2018 •

edited

Loading