Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

util: add computeTime option to inspect #19994

Closed
wants to merge 1 commit into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 9 additions & 2 deletions doc/api/util.md
Original file line number Diff line number Diff line change
Expand Up @@ -408,11 +408,11 @@ changes:
TODO(BridgeAR): Deprecate `maxArrayLength` and replace it with
`maxEntries`.
-->
* `maxArrayLength` {number} Specifies the maximum number of `Array`,
* `maxArrayLength` {integer} Specifies the maximum number of `Array`,
[`TypedArray`][], [`WeakMap`][] and [`WeakSet`][] elements to include when
formatting. Set to `null` or `Infinity` to show all elements. Set to `0` or
negative to show no elements. **Default:** `100`.
* `breakLength` {number} The length at which an object's keys are split
* `breakLength` {integer} The length at which an object's keys are split
across multiple lines. Set to `Infinity` to format an object as a single
line. **Default:** `60` for legacy compatibility.
* `compact` {boolean} Setting this to `false` changes the default indentation
Expand All @@ -422,6 +422,13 @@ changes:
objects the same as arrays. Note that no text will be reduced below 16
characters, no matter the `breakLength` size. For more information, see the
example below. **Default:** `true`.
* `budget` {integer} This limits the maximum time spend inspecting an object.
The budget corresponds roughly to the number of properties that are
inspected. If the object exceeds that complexity while inspecting, the
inspection is continued up to one more second. If the inspection does not
complete in that second, it will limit all further inspection to the
absolute minimum and an `INSPECTION_ABORTED` warning is emitted.
**Default:** `Infinity`.
* Returns: {string} The representation of passed object

The `util.inspect()` method returns a string representation of `object` that is
Expand Down
83 changes: 60 additions & 23 deletions lib/util.js
Original file line number Diff line number Diff line change
Expand Up @@ -99,7 +99,8 @@ const inspectDefaultOptions = Object.seal({
showProxy: false,
maxArrayLength: 100,
breakLength: 60,
compact: true
compact: true,
budget: Infinity
});

const kObjectType = 0;
Expand Down Expand Up @@ -406,24 +407,27 @@ function inspect(value, opts) {
maxArrayLength: inspectDefaultOptions.maxArrayLength,
breakLength: inspectDefaultOptions.breakLength,
indentationLvl: 0,
compact: inspectDefaultOptions.compact
compact: inspectDefaultOptions.compact,
budget: inspectDefaultOptions.budget
};
// Legacy...
if (arguments.length > 2) {
if (arguments[2] !== undefined) {
ctx.depth = arguments[2];
}
if (arguments.length > 3 && arguments[3] !== undefined) {
ctx.colors = arguments[3];
if (arguments.length > 1) {
// Legacy...
if (arguments.length > 2) {
if (arguments[2] !== undefined) {
ctx.depth = arguments[2];
}
if (arguments.length > 3 && arguments[3] !== undefined) {
ctx.colors = arguments[3];
}
}
}
// Set user-specified options
if (typeof opts === 'boolean') {
ctx.showHidden = opts;
} else if (opts) {
const optKeys = Object.keys(opts);
for (var i = 0; i < optKeys.length; i++) {
ctx[optKeys[i]] = opts[optKeys[i]];
// Set user-specified options
if (typeof opts === 'boolean') {
ctx.showHidden = opts;
} else if (opts) {
const optKeys = Object.keys(opts);
for (var i = 0; i < optKeys.length; i++) {
ctx[optKeys[i]] = opts[optKeys[i]];
}
}
}
if (ctx.colors) ctx.stylize = stylizeWithColor;
Expand Down Expand Up @@ -619,18 +623,45 @@ function noPrototypeIterator(ctx, value, recurseTimes) {
}
}

function getClockTime(start) {
const ts = process.hrtime(start);
return ts[0] * 1e3 + ts[1] / 1e6;
}

// Note: using `formatValue` directly requires the indentation level to be
// corrected by setting `ctx.indentationLvL += diff` and then to decrease the
// value afterwards again.
function formatValue(ctx, value, recurseTimes) {
// Primitive types cannot have properties
// Primitive types cannot have properties.
if (typeof value !== 'object' && typeof value !== 'function') {
return formatPrimitive(ctx.stylize, value, ctx);
}
if (value === null) {
return ctx.stylize('null', 'null');
}

if (ctx.budget < 0) {
if (ctx.stop === true) {
const name = getConstructorName(value) || value[Symbol.toStringTag];
return ctx.stylize(`[${name || 'Object'}]`, 'special');
}
if (ctx.time === undefined) {
ctx.time = process.hrtime();
} else if (getClockTime(ctx.time) > 1e3) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this necessary? Leaving out wall time tracking results in a simpler algorithm.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The point is: without this it is hard to tell how much time this will actually need on different CPUs. Using the wall time is future proof by always delivering the best result with a best effort mechanism.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What I mean is, is tracking any kind of time necessary?

What you call complexity, I would call budget. You start with a fixed budget and spend it until it's gone.

Since you have that kind of logic in place already, and since it's deterministic and clock agnostic, why also track time?

Copy link
Member Author

@BridgeAR BridgeAR May 28, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Budget is indeed a good description. I am just not sure if this would be understood by looking at a option named budget.

Relying on the budget completely without checking the wall time as well means I can measure the time it takes on my machine and estimate a arbitrary time limit that should not be exceeded in the default case (e.g. 1000-1250 ms as currently done). However, we also have Raspberry PIs and similar and their CPUs are much much slower and the same budget would get spend slower and therefore block the event loop longer. Our CPUs in general get faster over time with new inventions though, so the current default case for a fast machine would soon drop and the budget is spend faster. Meaning the maximum time the event loop would be allowed to be blocked would drop to e.g., 250ms instead of the current limit.

Using both together makes sure that it will always be around the 1000-1250ms range. That is the reason why I would like to have the combination of both, even though it is not fully deterministic after spending the complete budget.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's a fair point. Have you considered splitting it out into two separate options, one for budget/complexity and one for wall time? Or are you saying that you feel a single option is best?

Copy link
Member Author

@BridgeAR BridgeAR May 28, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel a single option is best for two reasons:

  • We already have to many options in util inspect and the more we add, the more complicated it gets for the user. I believe we should just have very solid defaults while allowing the user to also change some things that are definitely necessary in some cases.
  • I do not see a necessity for having a fine grained control over this. The option is meant to prevent the event loop from being blocked to long while being able to also opt out of that or to stricten the rule further (by setting the budget to <= 0 even though the minimum time is still set to 1 second). The question is: is it necessary for the user to allow util.inspect to bail out before one second passed? I personally doubt that.

process.emitWarning('util.inspect took to long.', {
code: 'INSPECTION_ABORTED',
detail: 'util.inspect() received an object that was very big and ' +
'complex to inspect. Further inspection was limited to a ' +
'minimum to stop blocking the event loop.'
});
// Since we only measure the time each 1e5 the output should be almost
// deterministic.
ctx.stop = true;
}
// Subtract 1e5 to know when to check again.
ctx.budget += 1e5;
}

if (ctx.showProxy) {
const proxy = getProxyDetails(value);
if (proxy !== undefined) {
Expand All @@ -639,11 +670,11 @@ function formatValue(ctx, value, recurseTimes) {
}

// Provide a hook for user-specified inspect functions.
// Check that value is an object with an inspect function on it
// Check that value is an object with an inspect function on it.
if (ctx.customInspect) {
const maybeCustom = value[customInspectSymbol];
if (typeof maybeCustom === 'function' &&
// Filter out the util module, its inspect function is special
// Filter out the util module, its inspect function is special.
maybeCustom !== exports.inspect &&
// Also filter out any prototype objects using the circular check.
!(value.constructor && value.constructor.prototype === value)) {
Expand Down Expand Up @@ -685,7 +716,7 @@ function formatRaw(ctx, value, recurseTimes) {

let extrasType = kObjectType;

// Iterators and the rest are split to reduce checks
// Iterators and the rest are split to reduce checks.
if (value[Symbol.iterator]) {
noIterator = false;
if (Array.isArray(value)) {
Expand Down Expand Up @@ -766,7 +797,9 @@ function formatRaw(ctx, value, recurseTimes) {
}
base = dateToISOString(value);
} else if (isError(value)) {
// Make error with message first say the error
// Normalize budget because error inspection is very slow.
ctx.budget -= 5;
// Make error with message first say the error.
base = formatError(value);
// Wrap the error in brackets in case it has no stack trace.
const stackStart = base.indexOf('\n at');
Expand Down Expand Up @@ -885,6 +918,7 @@ function formatRaw(ctx, value, recurseTimes) {
}
ctx.seen.pop();

ctx.budget += output.length;
return reduceToSingleString(ctx, output, base, braces);
}

Expand Down Expand Up @@ -1057,8 +1091,9 @@ function formatTypedArray(ctx, value, recurseTimes) {
formatBigInt;
for (var i = 0; i < maxLength; ++i)
output[i] = elementFormatter(ctx.stylize, value[i]);
if (remaining > 0)
if (remaining > 0) {
output[i] = `... ${remaining} more item${remaining > 1 ? 's' : ''}`;
}
if (ctx.showHidden) {
// .buffer goes last, it's not a primitive like the others.
ctx.indentationLvl += 2;
Expand Down Expand Up @@ -1247,6 +1282,8 @@ function formatProperty(ctx, value, recurseTimes, key, type) {
} else if (keyStrRegExp.test(key)) {
name = ctx.stylize(key, 'name');
} else {
// Normalize budget because replacing keys is slow.
ctx.budget -= 3;
name = ctx.stylize(strEscape(key), 'string');
}
return `${name}:${extra}${str}`;
Expand Down
29 changes: 29 additions & 0 deletions test/parallel/test-util-inspect-long-running.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
'use strict';
const common = require('../common');

// `util.inspect` is capable of computing a string that is bigger than 2 ** 28
// in one second, so let's just skip this test on 32bit systems.
common.skipIf32Bits();

// Test that big objects are running only up to the maximum complexity plus ~1
// second.

const util = require('util');

// Create a difficult to stringify object. Without the limit this would crash.
let last = {};
const obj = last;

for (let i = 0; i < 1000; i++) {
last.next = { circular: obj, last, obj: { a: 1, b: 2, c: true } };
last = last.next;
obj[i] = last;
}

common.expectWarning(
'Warning',
'util.inspect took to long.',
'INSPECTION_ABORTED'
);

util.inspect(obj, { depth: Infinity, budget: 1e6 });