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

Degradation of performance console.log on master #19977

Closed
ex1st opened this issue Apr 12, 2018 · 6 comments
Closed

Degradation of performance console.log on master #19977

ex1st opened this issue Apr 12, 2018 · 6 comments

Comments

@ex1st
Copy link

ex1st commented Apr 12, 2018

  • Version: 10.0.0-nightly201804120aab8ff602 (V8 6.6.346.23-node.2)
  • Platform: Linux (Ubuntu 17.10) x86_64
  • Subsystem:
let i = 0;

const obj = {};

while (i++ < 1500) {
	obj[i] = {};
}

const circular = {};

for (const k of Object.keys(obj)) {
	circular[k] = obj[k];
	obj[k]._circular = circular ;
	obj[k]._obj = obj;
}

console.log(obj);

8.10.0 - performed immediately
master (V8 6.6 and V8 6.5 both) - utilized 100% CPU and frozen for a long time and crashed process.

I think a problem with resolving circular links.

<--- Last few GCs --->

[27724:0x3786f60]   148251 ms: Mark-sweep 1155.0 (1397.3) -> 1155.0 (1397.3) MB, 1530.5 / 0.0 ms  allocation failure GC in old space requested
[27724:0x3786f60]   148777 ms: Mark-sweep 1155.0 (1397.3) -> 1155.0 (1339.3) MB, 526.1 / 0.0 ms  last resort GC in old space requested
[27724:0x3786f60]   149313 ms: Mark-sweep 1155.0 (1339.3) -> 1155.0 (1318.3) MB, 535.9 / 0.0 ms  last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x375efed8427d]
Security context: 0x36bfc73a06a9 <JSObject>
    1: handleWriteReq(aka handleWriteReq) [internal/stream_base_commons.js:20] [bytecode=0x32e43edfa9e9 offset=139](this=0x1d98fd5022e1 <undefined>,req=0x160bce3f12b1 <WriteWrap map = 0x298316604d71>,data=0x160bce3f0f91 <Very long string[135621394]>,encoding=0x36bfc73b1529 <String[4]: utf8>)
    2: writeGeneric(aka writeGeneric) [internal/stream_base_commons...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node::Abort() [node]
 2: 0x87a44c [node]
 3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
 5: v8::internal::Factory::NewRawOneByteString(int, v8::internal::PretenureFlag) [node]
 6: v8::internal::String::SlowFlatten(v8::internal::Handle<v8::internal::ConsString>, v8::internal::PretenureFlag) [node]
 7: v8::internal::String::Flatten(v8::internal::Handle<v8::internal::String>, v8::internal::PretenureFlag) [node]
 8: v8::String::WriteUtf8(char*, int, int*, int) const [node]
 9: node::StringBytes::Write(v8::Isolate*, char*, unsigned long, v8::Local<v8::Value>, node::encoding, int*) [node]
10: int node::StreamBase::WriteString<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&) [node]
11: void node::StreamBase::JSMethod<node::LibuvStreamWrap, &(int node::StreamBase::WriteString<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&))>(v8::FunctionCallbackInfo<v8::Value> const&) [node]
12: v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [node]
13: 0xace61a [node]
14: v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) [node]
15: 0x375efed8427d
Aborted (core dumped)
@richardlau
Copy link
Member

Possibly related to #19405?

@BridgeAR
Copy link
Member

That is indeed somewhat related. The problem here is that the object is huge. It is quite a lot of work to compute that. Before, there was no circular check because the object depth was already reached before. This will also fail on Node.js 8 or 9 if the util.inspect depth is set to 4 or higher. I plan on limiting the object keys printed by default to 100 just like it is done with arrays. That would also solve the problem here. I am going to wrap my head around finding a even nicer solution also by checking what is using most memory in this case.

@BridgeAR
Copy link
Member

I had a look at the performance and about 90% of the time is spend calling Object.keys. Due to the limit change, it will not only call Object.keys 1500 * 1500 times but 1500 * 1500 * n (I did not check exactly what is happening and just had a glance at it). One problem is that to print "circular", we have to first get the keys. I would love to move it up, but that would break the output of e.g., empty objects etc.

@ex1st
Copy link
Author

ex1st commented Apr 16, 2018

Similar to #19405

@ex1st ex1st closed this as completed Apr 16, 2018
@BridgeAR
Copy link
Member

This specific issue got fixed by #20007.

@BridgeAR
Copy link
Member

@ex1st this is how your example runs on my machine with the mentioned patch applied:

// Before the patch:
// run: 165971.450ms

// After the patch:
// run: 7377.811ms

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants