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

Node 8 - missing stacks #76

Closed
davidmarkclements opened this issue Aug 17, 2017 · 7 comments
Closed

Node 8 - missing stacks #76

davidmarkclements opened this issue Aug 17, 2017 · 7 comments

Comments

@davidmarkclements
Copy link
Owner

Given:

setInterval(() => { x(()=>{}) }, 10)

function x (cb) {
  setTimeout(cb, 10, Math.round(Math.random()) ? null : Error(), {x: Math.random()})
}

Node 6.11.2:
image

Node 8.4.0:
image

@davidmarkclements
Copy link
Owner Author

#75 may be relevant

@davidmarkclements
Copy link
Owner Author

This is macOs but anecdotally I've seen same on linux

Not an interpretation problem on 0x part, stacks simply aren't being captured

node 23355 629980: profile-1ms:
              libsystem_kernel.dylib`__error+0x9
              node`0x5

node 23355 630016: profile-1ms:
              node`v8::internal::TimerEventScope<v8::internal::TimerEventExecute>::LogTimerEvent(v8::internal::Logger::StartEnd)
              node`0x5

node 23355 630064: profile-1ms:
              node`0x5

node 23355 630136: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 630196: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 630232: profile-1ms:
              node`0x5

node 23355 630328: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 630364: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 630412: profile-1ms:
              node`0x5

node 23355 630892: profile-1ms:
              node`v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastHoleyObjectElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)3> >::GetDetails(v8::internal::JSObject*, unsigned int)+0x1
              node`0x5

node 23355 630940: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 631360: profile-1ms:
              node`0x5

node 23355 631516: profile-1ms:
              libsystem_pthread.dylib`pthread_getspecific+0x9
              node`0x5

node 23355 631684: profile-1ms:
              node`v8::internal::PerIsolateAssertScope<(v8::internal::PerIsolateAssertType)0, true>::IsAllowed(v8::internal::Isolate*)
              node`0x5

node 23355 631912: profile-1ms:
              node`0x5

node 23355 632128: profile-1ms:
              node`0x5

node 23355 632152: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 632417: profile-1ms:
              node`0x5

node 23355 632504: profile-1ms:
              BytecodeHandler:JumpIfNotHole
              BytecodeHandler:CallUndefinedReceiver2
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver1
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver1
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver1
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver2
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 632637: profile-1ms:
              BytecodeHandler:Nop
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 632757: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 632793: profile-1ms:
              node`0x5

node 23355 632806: profile-1ms:
              Stub:CEntryStub
              BytecodeHandler:CreateObjectLiteral
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver1
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallProperty0
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver1
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallUndefinedReceiver2
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 632842: profile-1ms:
              node`0x5

node 23355 632961: profile-1ms:
              Stub:JSEntryStub
              node`0x5

node 23355 633033: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 633069: profile-1ms:
              BytecodeHandler:TestEqualStrict
              BytecodeHandler:CallProperty1
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 633129: profile-1ms:
              node`0x5

node 23355 633250: profile-1ms:
              Stub:JSEntryStub
              node`0x5

node 23355 633346: profile-1ms:
              Builtin:CallFunction_ReceiverIsAny
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 633526: profile-1ms:
              node`v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
              BytecodeHandler:CallProperty0
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 633574: profile-1ms:
              node`v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastHoleyObjectElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)3> >::GetEntryForIndex(v8::internal::Isolate*, v8::internal::JSObject*, v8::internal::FixedArrayBase*, unsigned int)
              node`0x5

node 23355 633694: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 633790: profile-1ms:
              node`0x5

node 23355 633886: profile-1ms:
              node`0x5

node 23355 634138: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 634198: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 634283: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 634500: profile-1ms:
              node`0x5

node 23355 634716: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 635016: profile-1ms:
              node`0x5

node 23355 635448: profile-1ms:
              node`0x5

node 23355 635508: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 635616: profile-1ms:
              node`0x5

node 23355 635820: profile-1ms:
              libsystem_pthread.dylib`pthread_getspecific
              node`0x5

node 23355 636024: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 636239: profile-1ms:
              Builtin:StoreICStrict
              BytecodeHandler:StaNamedPropertyStrict
              Builtin:InterpreterEntryTrampoline
              BytecodeHandler:CallProperty1
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 636251: profile-1ms:
              Stub:CallICStubANY, DISALLOW_TAIL_CALLS
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 636323: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 636395: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 636708: profile-1ms:
              node`0x5

node 23355 636732: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 636804: profile-1ms:
              node`void v8::internal::LookupIterator::Start<true>()
              node`0x5

node 23355 636888: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 636924: profile-1ms:
              Builtin:ArgumentsAdaptorTrampoline
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 637008: profile-1ms:
              node`node::AsyncWrap::EmitBefore(node::Environment*, double)+0x1
              node`0x5

node 23355 637080: profile-1ms:
              libsystem_kernel.dylib`__error
              node`0x5

node 23355 637212: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 637248: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 637560: profile-1ms:
              Stub:JSEntryStub
              node`0x5

node 23355 637716: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 638028: profile-1ms:
              BytecodeHandler:StackCheck
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 638064: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 638148: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 638184: profile-1ms:
              libsystem_pthread.dylib`pthread_getspecific
              node`0x5

node 23355 638341: profile-1ms:
              node`0x5

node 23355 638413: profile-1ms:
              node`0x5

node 23355 638545: profile-1ms:
              node`0x5

node 23355 638629: profile-1ms:
              node`0x5

node 23355 638641: profile-1ms:
              Builtin:InterpreterEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 638665: profile-1ms:
              node`0x5

node 23355 638761: profile-1ms:
              node`0x5

node 23355 638917: profile-1ms:
              node`0x5

node 23355 638965: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 638989: profile-1ms:
              node`0x5

node 23355 639025: profile-1ms:
              Builtin:CallFunction_ReceiverIsAny
              Stub:JSEntryStub
              node`0x5

node 23355 639085: profile-1ms:
              node`0x5

node 23355 639133: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 639181: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 639204: profile-1ms:
              node`v8::base::Mutex::Lock()
              node`0x5

node 23355 639288: profile-1ms:
              BytecodeHandler:Nop
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 639372: profile-1ms:
              node`0x5

node 23355 639696: profile-1ms:
              Builtin:ArgumentsAdaptorTrampoline
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 639792: profile-1ms:
              BytecodeHandler:LdaNamedProperty
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 639865: profile-1ms:
              node`0x5

node 23355 639877: profile-1ms:
              node`0x5

node 23355 639925: profile-1ms:
              libsystem_kernel.dylib`__error+0x9
              node`0x5

node 23355 639949: profile-1ms:
              BytecodeHandler:LdaCurrentContextSlot
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 639997: profile-1ms:
              node`v8::internal::PerIsolateAssertScope<(v8::internal::PerIsolateAssertType)0, true>::IsAllowed(v8::internal::Isolate*)+0xa
              node`0x5

node 23355 640057: profile-1ms:
              node`0x5

node 23355 640202: profile-1ms:
              Stub:CEntryStub
              Builtin:CompileOptimizedConcurrent
              BytecodeHandler:CallProperty1
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 640203: profile-1ms:
              Stub:CEntryStub
              Builtin:CompileOptimizedConcurrent
              BytecodeHandler:CallProperty1
              Builtin:InterpreterEntryTrampoline
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 640204: profile-1ms:
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd

node 23355 640228: profile-1ms:
              node`v8::internal::compiler::Node::New(v8::internal::Zone*, unsigned int, v8::internal::compiler::Operator const*, int, v8::internal::compiler::Node* const*, bool)+0x6
              Stub:CEntryStub
              Builtin:CompileOptimizedConcurrent
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 640229: profile-1ms:
              Stub:CEntryStub
              Builtin:CompileOptimizedConcurrent
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 640230: profile-1ms:
              Stub:CEntryStub
              Builtin:CompileOptimizedConcurrent
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 640231: profile-1ms:
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd

node 23355 640232: profile-1ms:
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd

node 23355 640233: profile-1ms:
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd

node 23355 640234: profile-1ms:
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd

node 23355 640235: profile-1ms:
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd

node 23355 640242: profile-1ms:
              node`0x5

node 23355 640483: profile-1ms:
              node`0x5

node 23355 640519: profile-1ms:
              node`0x5

node 23355 640543: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 640603: profile-1ms:
              node`0x5

node 23355 640639: profile-1ms:
              node`v8::internal::Logger::ApiEntryCall(char const*)+0x1
              node`0x5

node 23355 640915: profile-1ms:
              node`0x5

node 23355 641107: profile-1ms:
              node`0x5

node 23355 641155: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 641238: profile-1ms:
              node`0x5

node 23355 641419: profile-1ms:
              Stub:CallApiCallbackStub
              LazyCompile:*listOnTimeout timers.js:205
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 641684: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 641985: profile-1ms:
              Stub:CallApiCallbackStub
              LazyCompile:*listOnTimeout timers.js:205
              Builtin:JSEntryTrampoline
              Stub:JSEntryStub
              node`0x5

node 23355 642033: profile-1ms:
              node`v8::Object::Get(unsigned int)+0x1
              node`0x5

node 23355 642190: profile-1ms:
              libsystem_kernel.dylib`kevent+0xa
              node`0x5

node 23355 642406: profile-1ms:
              node`0x5





@davepacheco
Copy link

Some of these look like cases where there was no frame pointer pushed onto the stack, as often happens when "-fomit-frame-pointer" is used to compile C code. I'm not sure if that's what's going on. It's also possible that the newer version of V8 no longer pushes frame pointers upon entry into its functions. If true, I think that would basically destroy the ability to profile from tools like DTrace or to use most debuggers (e.g., gdb, mdb, lldb), including postmortem debugging. With luck, this behavior might be configurable.

To say for sure, you'd either need to look at the V8 source to see what it does, or look at the instructions for compiled JavaScript functions and see if they start with the usual instruction prologue.

Some of the information here may help as background:
http://dtrace.org/blogs/dap/2013/11/20/understanding-dtrace-ustack-helpers/

@davidmarkclements
Copy link
Owner Author

hey @davepacheco ! - ok so I should update this further - I've mistakenly posted the post-processed stacks (processed with http://npm.im/perf-sym) - don't have the originals but here's another run (also with out delayed tracing) with original stacks - it still has missing info frames in node 8.3

too long for gh comments:
https://gist.github.com/davidmarkclements/b4c7f1e4aba2b6a75340ff478f5585cb

@davepacheco
Copy link

The frames there are consistent with the ustack helper basically not working at all. It may be something small, but there's no silver bullet for this. We basically have to debug the ustack helper from first principles. (As I mention in the blog post, it would probably be easier to fix this in mdb_v8 (or llnode) first.)

@hashseed
Copy link

I don't have a lot of insight into your profiler. But I assume that it periodically captures the stack and walks it, trying to attribute each frame to functions, either ones compiled by V8 or ones from C++. This does not work with the new bytecode interpreter though. All you get are ticks inside bytecode handlers.

V8's own profiler knows how to deal with interpreted frames by extracting the pointer to the bytecode array from the frame. You could teach ustack helper to do the same?

@davidmarkclements
Copy link
Owner Author

ok so here's the thing - if you run the test script for long enough eventually the missing stacks turn up

I guess since we're profiling every ms the JS stacks might be able to sit between the ms ... ?

Maybe Turbofans just gotten really really fast at executing the actual JS functions, and the big increase in V8 related frames is just optimization noise thats hogging CPU for a while, initially

For normal cases (like a web server) there's actually no (perceptible) effect on this oddity,
on top of that, using v8 isolate files as an alternative doesn't seem to map effectively, the "top of stack" paradigm doesn't really seem to translate... so I'm going to close this for now.

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