util: improve inspect performance #14881

BridgeAR · 2017-08-17T01:17:50Z

I reworked a couple of things in util inspect for performance. The code is fully covered.

EDIT: Updated the comment here and benchmarks.

 util/format.js type="no-replace" n=2000000                                1676.61 %        *** 6.038361e-60
 util/inspect-array.js type="denseArray_showHidden" len=100000 n=1000        87.89 %        *** 3.315801e-79
 util/inspect-array.js type="denseArray" len=100000 n=1000                   68.83 %        *** 5.648717e-52
 util/inspect-array.js type="mixedArray" len=100000 n=1000                   21.22 %        *** 2.438066e-52
 util/inspect-array.js type="sparseArray" len=100000 n=1000                   6.87 %        *** 9.551672e-50
 util/inspect-proxy.js n=1000000                                            418.34 %        *** 5.193464e-71
 util/inspect.js option="colors" method="Array" n=2000000                   121.92 %        *** 1.136217e-39
 util/inspect.js option="colors" method="Date" n=2000000                    294.42 %        *** 3.899375e-18
 util/inspect.js option="colors" method="Error" n=2000000                   507.31 %        *** 6.416333e-18
 util/inspect.js option="colors" method="Object_deep_ln" n=2000000          257.20 %        *** 8.804036e-23
 util/inspect.js option="colors" method="Object_empty" n=2000000            704.27 %        *** 8.422940e-46
 util/inspect.js option="colors" method="Object" n=2000000                  372.04 %        *** 3.430467e-19
 util/inspect.js option="colors" method="Set" n=2000000                     443.65 %        *** 7.503642e-30
 util/inspect.js option="colors" method="String_boxed" n=2000000            458.19 %        *** 4.199961e-23
 util/inspect.js option="colors" method="String_complex" n=2000000          875.46 %        *** 4.377511e-42
 util/inspect.js option="colors" method="String" n=5000000                 2209.03 %        *** 3.336942e-23
 util/inspect.js option="colors" method="TypedArray_extra" n=2000000        269.77 %        *** 6.353860e-22
 util/inspect.js option="colors" method="TypedArray" n=2000000              244.82 %        *** 1.157433e-47
 util/inspect.js option="none" method="Array" n=2000000                     298.39 %        *** 6.163207e-35
 util/inspect.js option="none" method="Date" n=2000000                      308.41 %        *** 3.828139e-26
 util/inspect.js option="none" method="Error" n=2000000                     499.46 %        *** 2.519987e-17
 util/inspect.js option="none" method="Object_deep_ln" n=2000000            470.60 %        *** 7.069515e-27
 util/inspect.js option="none" method="Object_empty" n=2000000              703.54 %        *** 5.821877e-41
 util/inspect.js option="none" method="Object" n=2000000                    678.48 %        *** 1.752143e-21
 util/inspect.js option="none" method="Set" n=2000000                       739.62 %        *** 5.402939e-18
 util/inspect.js option="none" method="String_boxed" n=2000000              483.94 %        *** 2.756513e-37
 util/inspect.js option="none" method="String_complex" n=2000000           1082.41 %        *** 3.900304e-64
 util/inspect.js option="none" method="String" n=5000000                   3954.65 %        *** 1.558337e-26
 util/inspect.js option="none" method="TypedArray_extra" n=2000000          410.59 %        *** 1.364578e-19
 util/inspect.js option="none" method="TypedArray" n=2000000                387.47 %        *** 1.789663e-23
 util/inspect.js option="showHidden" method="Array" n=2000000               272.92 %        *** 2.332172e-29
 util/inspect.js option="showHidden" method="Date" n=2000000                307.75 %        *** 4.581806e-16
 util/inspect.js option="showHidden" method="Error" n=2000000               254.46 %        *** 1.552997e-19
 util/inspect.js option="showHidden" method="Object_deep_ln" n=2000000      422.07 %        *** 4.184839e-46
 util/inspect.js option="showHidden" method="Object_empty" n=2000000        665.61 %        *** 2.095402e-24
 util/inspect.js option="showHidden" method="Object" n=2000000              626.02 %        *** 6.570478e-39
 util/inspect.js option="showHidden" method="Set" n=2000000                 815.83 %        *** 3.634105e-32
 util/inspect.js option="showHidden" method="String_boxed" n=2000000        680.82 %        *** 3.104074e-27
 util/inspect.js option="showHidden" method="String_complex" n=2000000     1058.45 %        *** 5.543800e-49
 util/inspect.js option="showHidden" method="String" n=5000000             3473.09 %        *** 6.496121e-29
 util/inspect.js option="showHidden" method="TypedArray_extra" n=2000000    345.93 %        *** 9.418444e-36
 util/inspect.js option="showHidden" method="TypedArray" n=2000000          316.96 %        *** 4.742310e-35

The main optimizations are

Removed visibleKeys
Removed proxy cache
Removed Object.assign
No key concatenating anymore
No key recalculating anymore
Improved indentation logic
Improved string escape logic
Added many fast paths
Optimized code branches a lot
Optimized (boxed) primitive handling
Inline code if possible
Only check extra keys if necessary

Besides that there were lots of smaller optimizations, the
code got a bit cleaned up and a few more tests got in.

Also two bug fixes came.

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

Affected core subsystem(s)

util, benchmark

andrasq · 2017-08-17T17:14:49Z

lib/util.js

    formatter = formatArray;
+  } else if (isMapIterator(value)) {


a long series of if - else if - else if statements can also be formatted as a switch (true) { ... } (note that switch does a strict comparison, ie matches not truthy but true). Strictly a layout issue, otherwise completely equivalent, both O(n) in the number of tests.

I you prefer that I can change it, otherwise I would just keep it as is.

addaleax

This is great work, thank you!

addaleax · 2017-08-17T18:42:03Z

lib/util.js

+    if (ctx.seen === undefined) {
+      ctx.seen = [];
+      // A customInspect could be set only for partial objects.
+      // To prevent a breaking change, fill the lazy added array with all


grammar nit: lazy → lazily

addaleax · 2017-08-17T18:42:22Z

lib/util.js

+  const customInspect = isCustomInspect(ctx, value);
+  if (customInspect !== undefined) {
+    if (ctx.seen === undefined) {
+      ctx.seen = [];


ctx.seen = [...ctx.seenSet]?

Also, I, personally, would be fine with having seen just be a getter/setter pair.

Ref #14881 (comment)

addaleax · 2017-08-17T18:47:12Z

lib/util.js

@@ -300,12 +298,9 @@ function stylizeNoColor(str, styleType) {

 function arrayToHash(array) {


I feel like this could just be turned into a Set as well

I tried that and it was actually a bit slower in my benchmarks. When 6.1 lands I might have another look at it.

addaleax · 2017-08-17T18:48:12Z

lib/util.js

@@ -318,6 +313,21 @@ function ensureDebugIsInitialized() {
 }


+function isCustomInspect(ctx, value) {


This really sounds like it would return a boolean ;)

lib/util.js

addaleax · 2017-08-17T18:56:28Z

Also, sorry for the merge conflict, I fixed Evan’s nit while landing my PR.

BridgeAR · 2017-08-17T19:51:48Z

@addaleax I addressed your comments and don't worry about the conflicts, I was aware of those changes and I'll rebase after #14880 lands :)
Those are minor changes anyway.

BridgeAR · 2017-08-18T14:43:41Z

lib/util.js

-  }
+  // Using an array here is actually better for the average case then using
+  // a Set. `seen` will only check for the depth and will never grow to large.
+  if (ctx.seen.includes(value))


I reverted my change to a Set here: the seen part will only contain up to ctx.depth + 1 elements and in the regular case that is three. Using a Set for such a low amount of elements seems unnecessary, as it increases the code complexity due to having to handle both, an array and a set in case customInspect is set.

BridgeAR · 2017-08-21T04:16:12Z

I rebased and added a new array fast path. So PTAL

Just for fun - this is how the profiling looks like with Array(1e5).fill(1)

 [Summary]:
   ticks  total  nonlib   name
    261    0.6%    0.6%  JavaScript
  39502   94.0%   94.3%  C++
   1797    4.3%    4.3%  GC
    129    0.3%          Shared libraries
   2147    5.1%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
  37497   99.2%   89.2%  v8::internal::Runtime_ObjectKeys(int, v8::internal::Object**, v8::internal::Isolate*)
     75    0.2%    0.2%  v8::internal::Builtin_ObjectGetOwnPropertyDescriptor(int, v8::internal::Object**, v8::internal::Isolate*)

0.6 % JavaScript 🤣

BridgeAR · 2017-08-21T04:49:30Z

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

refack

1 nit otherwise LGTM

refack · 2017-08-17T18:20:46Z

lib/util.js

@@ -211,28 +211,28 @@ function debuglog(set) {
 * @param {Object} obj The object to print out.
 * @param {Object} opts Optional options object that alters the output.
 */
-/* legacy: obj, showHidden, depth, colors*/
-function inspect(obj, opts) {
+function inspect(obj, opts, /* legacy */depth, /* legacy */colors) {


Not worth it.

changes util.inspect.length

drives my IDE crazy

Well, I do not have a strong opinion.
I went ahead and changed it back to a similar way as before to make you happy ;-)

BridgeAR · 2017-08-21T12:58:26Z

So I pushed a bit more code and updated the benchmarks. The result is pretty decent now.

BridgeAR · 2017-08-21T18:35:19Z

Ok, the new benchmarks are outdated again as I was able to improve some more things that had significant impact on showHidden. So just think of most showHidden results +100%.

BridgeAR · 2017-08-24T00:16:48Z

So after looking at it again I added some final changes. The benchmarks are updated in the main part. As the code still changed significantly, please take a close look again. @addaleax @refack @andrasq

And I have an issue with one test running this locally but I can not explain why the test is failing. I get the following output. @bnoordhuis you wrote that test, would you be so kind and have a look at it? Because I do not see the connection of the error to my changes...

	async-hooks doctool inspector known_issues message parallel pseudo-tty sequential \
	addons addons-napi
[02:05|%  91|+ 1642|-   0]: release stack_overflow_async length differs.       
expect=4
actual=2
patterns:
pattern = ^RangeError\:\ Maximum\ call\ stack\ size\ exceeded$
pattern = ^\ \ \ \ at\ f\ \(.*test.*message.*stack\_overflow\_async\.js\:.*\)$
pattern = ^\ \ \ \ at\ f\ \(.*test.*message.*stack\_overflow\_async\.js\:7\:.*\)$
pattern = ^\ \ \ \ at\ f\ \(.*test.*message.*stack\_overflow\_async\.js\:7\:.*\)$
outlines:
outline = (node:21361) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 2): RangeError: Maximum call stack size exceeded
outline = (node:21361) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
=== release stack_overflow_async ===                    
Path: message/stack_overflow_async
(node:21361) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 2): RangeError: Maximum call stack size exceeded
(node:21361) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
Command: out/Release/node --stack_trace_limit=3 /home/ruben/repos/node/node/test/message/stack_overflow_async.js
[02:46|% 100|+ 1785|-   1]: Done

addaleax · 2017-08-24T00:21:10Z

@BridgeAR That’s a really new test, and I’m pretty sure it’s not related to your PR

BridgeAR · 2017-08-24T02:45:18Z

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

BridgeAR · 2017-08-24T02:56:32Z

@addaleax the weird part is that is it happening only with this PR. On master it does not fail. It is reproducible for me on my local machine and also the CI fails exactly at this test. [EDIT] And the test passes if I call console.log() on top of the function call. Only calling console.log fails. [/EDIT]

BridgeAR · 2017-08-29T02:10:23Z

@bnoordhuis it would be nice if you could have a look at this PR because it somehow breaks this test even though there should not be any connection. The only way for me to fix the test is by calling process.stdout.write("") (or console.log()) somewhere before the test starts.

BridgeAR · 2017-09-05T11:52:47Z

@nodejs/collaborators PTAL

mcollina

LGTM with both CI and CITGM green. Those type of large scale perf improvements can lead to broken production code.

This should be semver-minor at least, and it should bake for LTS for some month before being backported.

In addition use the newer common.expectsError version. PR-URL: nodejs/node#14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

jasnell · 2017-09-20T15:52:38Z

This needs a backport pr to land in v8.x

PR-URL: #14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

In addition use the newer common.expectsError version. PR-URL: #14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

PR-URL: nodejs#14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

The main optimizations are - Removed visibleKeys - Removed proxy cache - Removed Object.assign - No key concatenating anymore - No key recalculating anymore - Improved indentation logic - Improved string escape logic - Added many fast paths - Optimized code branches a lot - Optimized (boxed) primitive handling - Inline code if possible - Only check extra keys if necessary - Guard against unnecessary more expensive calls This also fixes a bug with special array number keys as e.g. "00". Besides that there were lots of smaller optimizations, the code got a bit cleaned up and a few more tests got in. PR-URL: nodejs#14881 Fixes: nodejs#15288 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

This fixes a issue brought up in nodejs#15288. PR-URL: nodejs#14881 Refs: nodejs#15288 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

Remove unnecessary code parts and outdated code PR-URL: nodejs#14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

PR-URL: #14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

The main optimizations are - Removed visibleKeys - Removed proxy cache - Removed Object.assign - No key concatenating anymore - No key recalculating anymore - Improved indentation logic - Improved string escape logic - Added many fast paths - Optimized code branches a lot - Optimized (boxed) primitive handling - Inline code if possible - Only check extra keys if necessary - Guard against unnecessary more expensive calls This also fixes a bug with special array number keys as e.g. "00". Besides that there were lots of smaller optimizations, the code got a bit cleaned up and a few more tests got in. PR-URL: #14881 Fixes: #15288 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

This fixes a issue brought up in #15288. PR-URL: #14881 Refs: #15288 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

Remove unnecessary code parts and outdated code PR-URL: #14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

PR-URL: nodejs/node#14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

The main optimizations are - Removed visibleKeys - Removed proxy cache - Removed Object.assign - No key concatenating anymore - No key recalculating anymore - Improved indentation logic - Improved string escape logic - Added many fast paths - Optimized code branches a lot - Optimized (boxed) primitive handling - Inline code if possible - Only check extra keys if necessary - Guard against unnecessary more expensive calls This also fixes a bug with special array number keys as e.g. "00". Besides that there were lots of smaller optimizations, the code got a bit cleaned up and a few more tests got in. PR-URL: nodejs/node#14881 Fixes: nodejs/node#15288 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

This fixes a issue brought up in #15288. PR-URL: nodejs/node#14881 Refs: nodejs/node#15288 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

Remove unnecessary code parts and outdated code PR-URL: nodejs/node#14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

In addition use the newer common.expectsError version. PR-URL: nodejs/node#14881 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

MylesBorins · 2017-10-17T18:10:53Z

should this land in LTS? If so it will need to bake a bit longer.

Please change labels as appropriate

BridgeAR added benchmark Issues and PRs related to the benchmark subsystem. blocked PRs that are blocked by other issues or PRs. performance Issues and PRs related to the performance of Node.js. util Issues and PRs related to the built-in util module. labels Aug 17, 2017

BridgeAR mentioned this pull request Aug 17, 2017

util: use constructor name #14886

Closed

4 tasks

andrasq reviewed Aug 17, 2017

View reviewed changes

addaleax reviewed Aug 17, 2017

View reviewed changes

BridgeAR commented Aug 18, 2017

View reviewed changes

BridgeAR force-pushed the improve-inspect branch from 33adc94 to 6b87703 Compare August 21, 2017 04:02

refack approved these changes Aug 21, 2017

View reviewed changes

BridgeAR added the wip Issues and PRs that are still a work in progress. label Aug 23, 2017

BridgeAR force-pushed the improve-inspect branch from 30d4685 to 2716b99 Compare August 24, 2017 00:07

BridgeAR removed blocked PRs that are blocked by other issues or PRs. wip Issues and PRs that are still a work in progress. labels Aug 24, 2017

BridgeAR mentioned this pull request Aug 24, 2017

console: implement minimal console.group() #14910

Closed

4 tasks

jasnell requested a review from bnoordhuis August 29, 2017 04:45

BridgeAR mentioned this pull request Aug 31, 2017

test: remove faulty test case #15110

Closed

4 tasks

mcollina approved these changes Sep 5, 2017

View reviewed changes

jasnell added the backport-requested-v8.x label Sep 20, 2017

This was referenced Sep 20, 2017

benchmark: var to const #13757

Closed

Node.js 8.6.0 Release Proposal #15509

Merged

BridgeAR mentioned this pull request Sep 20, 2017

[v8.x backport] util: improve inspect performance #15512

Closed

4 tasks

jasnell added backported-to-v8.x and removed backport-requested-v8.x labels Sep 21, 2017

MylesBorins added baking-for-lts PRs that need to wait before landing in a LTS release. lts-watch-v6.x labels Oct 17, 2017

BridgeAR mentioned this pull request Dec 20, 2017

doc: warn about using util.inspect/util.format in prod #17791

Closed

3 tasks

MylesBorins removed the baking-for-lts PRs that need to wait before landing in a LTS release. label Aug 17, 2018

BridgeAR deleted the improve-inspect branch April 1, 2019 23:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

util: improve inspect performance #14881

util: improve inspect performance #14881

BridgeAR commented Aug 17, 2017 •

edited

Loading

andrasq Aug 17, 2017 •

edited

Loading

BridgeAR Aug 17, 2017

addaleax left a comment

addaleax Aug 17, 2017

BridgeAR Aug 17, 2017

addaleax Aug 17, 2017

BridgeAR Aug 17, 2017

BridgeAR Aug 18, 2017

addaleax Aug 17, 2017

BridgeAR Aug 17, 2017

addaleax Aug 17, 2017

BridgeAR Aug 17, 2017

addaleax commented Aug 17, 2017

BridgeAR commented Aug 17, 2017

BridgeAR Aug 18, 2017

BridgeAR commented Aug 21, 2017 •

edited

Loading

BridgeAR commented Aug 21, 2017

refack left a comment

refack Aug 17, 2017

BridgeAR Aug 21, 2017

BridgeAR commented Aug 21, 2017

BridgeAR commented Aug 21, 2017

BridgeAR commented Aug 24, 2017

addaleax commented Aug 24, 2017

BridgeAR commented Aug 24, 2017

BridgeAR commented Aug 24, 2017 •

edited

Loading

BridgeAR commented Aug 29, 2017

BridgeAR commented Sep 5, 2017

mcollina left a comment

jasnell commented Sep 20, 2017

MylesBorins commented Oct 17, 2017

		@@ -300,12 +298,9 @@ function stylizeNoColor(str, styleType) {

		function arrayToHash(array) {

		@@ -318,6 +313,21 @@ function ensureDebugIsInitialized() {
		}


		function isCustomInspect(ctx, value) {

util: improve inspect performance #14881

util: improve inspect performance #14881

Conversation

BridgeAR commented Aug 17, 2017 • edited Loading

Checklist

Affected core subsystem(s)

andrasq Aug 17, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

addaleax left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

addaleax commented Aug 17, 2017

BridgeAR commented Aug 17, 2017

Choose a reason for hiding this comment

BridgeAR commented Aug 21, 2017 • edited Loading

BridgeAR commented Aug 21, 2017

refack left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BridgeAR commented Aug 21, 2017

BridgeAR commented Aug 21, 2017

BridgeAR commented Aug 24, 2017

addaleax commented Aug 24, 2017

BridgeAR commented Aug 24, 2017

BridgeAR commented Aug 24, 2017 • edited Loading

BridgeAR commented Aug 29, 2017

BridgeAR commented Sep 5, 2017

mcollina left a comment

Choose a reason for hiding this comment

jasnell commented Sep 20, 2017

MylesBorins commented Oct 17, 2017

BridgeAR commented Aug 17, 2017 •

edited

Loading

andrasq Aug 17, 2017 •

edited

Loading

BridgeAR commented Aug 21, 2017 •

edited

Loading

BridgeAR commented Aug 24, 2017 •

edited

Loading