Open jondubois opened 10 years ago
bnoordhuis
commented
10 years ago The way strong-agent checks CPU usage in v0.4.14 is rather inefficient on some platforms but that's fixed in v0.1.0.
About the segfault, can you try capturing a backtrace in gdb? Here is how you do that:
$ gdb --args node server.js
> run
# wait for the segfault
> thread apply all backtraceCan you include the output of uname -a, node -p process.config and node -p process.versions? Thanks.
sam-github
commented
10 years ago Also, @jondubois, can you verify that the version of strong-agent you are using in both cases? Use slc -v to get the strong-agent version used by slc, and use npm ls | grep strong-agent to get the version you have installed in your app.
jondubois
commented
10 years ago uname -a
Linux ip-10-182-204-34 3.2.21-1.32.6.amzn1.x86_64 #1 SMP Sat Jun 23 02:32:15 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux
node -p process.config
{ target_defaults:
{ cflags: [],
default_configuration: 'Release',
defines: [ 'OPENSSL_NO_SSL2=1' ],
include_dirs: [],
libraries: [] },
variables:
{ clang: 0,
gcc_version: 44,
host_arch: 'x64',
node_install_npm: true,
node_prefix: '/',
node_shared_cares: false,
node_shared_http_parser: false,
node_shared_libuv: false,
node_shared_openssl: false,
node_shared_v8: false,
node_shared_zlib: false,
node_tag: '',
node_use_dtrace: false,
node_use_etw: false,
node_use_mdb: false,
node_use_openssl: true,
node_use_perfctr: false,
openssl_no_asm: 0,
python: '/data/opt/bin/python',
target_arch: 'x64',
uv_library: 'static_library',
uv_parent_path: '/deps/uv/',
uv_use_dtrace: false,
v8_enable_gdbjit: 0,
v8_enable_i18n_support: 0,
v8_no_strict_aliasing: 1,
v8_optimized_debug: 0,
v8_random_seed: 0,
v8_use_snapshot: false,
want_separate_host_toolset: 0 } }node -p process.versions v0.11.14
GDB backtrace (with commands used)
I ran this on a basic Node.js http server script (file: s2.js)
[root@ip-10-182-204-34 app]# gdb --args node s2
GNU gdb (GDB) Amazon Linux (7.6.1-51.24.amzn1)
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-amazon-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/local/bin/node...done.
(gdb) run
Starting program: /usr/local/bin/node s2
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
strong-agent dashboard is at https://strongops.strongloop.com
strong-agent using collector https://collector.strongloop.com:443
[New Thread 0x7ffff69e9700 (LWP 8352)]
[New Thread 0x7ffff61e8700 (LWP 8353)]
[New Thread 0x7ffff59e7700 (LWP 8354)]
[New Thread 0x7ffff51e6700 (LWP 8355)]
strong-agent v1.0.2 profiling app 's2' pid '8348'
strong-agent[8348] started profiling agent
strong-agent[8348] connected to collector
[New Thread 0x7ffff7ee4700 (LWP 8356)]
strong-agent[8348] starting cpu profiler
Program received signal SIGSEGV, Segmentation fault.
0x0000000000000000 in ?? ()
Missing separate debuginfos, use: debuginfo-install glibc-2.17-55.87.amzn1.x86_64 libgcc-4.4.6-3.45.amzn1.x86_64 libstdc++-4.4.6-3.45.amzn1.x86_64
(gdb) thread apply all backtrace
Thread 6 (Thread 0x7ffff7ee4700 (LWP 8356)):
#0 0x00007ffff6fa9c4d in sem_post () from /lib64/libpthread.so.0
#1 0x0000000000ae9c67 in v8::internal::ThreadEntry(void*) ()
#2 0x00007ffff6fa3f18 in start_thread () from /lib64/libpthread.so.0
#3 0x00007ffff6cd9b9d in clone () from /lib64/libc.so.6
Thread 5 (Thread 0x7ffff51e6700 (LWP 8355)):
#0 0x00007ffff6fa780d in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib64/libpthread.so.0
#1 0x0000000000b7a2f9 in uv_cond_wait (cond=<optimized out>,
mutex=<optimized out>) at ../deps/uv/src/unix/thread.c:324
#2 0x0000000000b6d35f in worker (arg=<optimized out>)
at ../deps/uv/src/threadpool.c:73
#3 0x0000000000b6dec1 in uv__thread_start (arg=<optimized out>)
at ../deps/uv/src/uv-common.c:278
#4 0x00007ffff6fa3f18 in start_thread () from /lib64/libpthread.so.0
#5 0x00007ffff6cd9b9d in clone () from /lib64/libc.so.6
Thread 4 (Thread 0x7ffff59e7700 (LWP 8354)):
#0 0x00007ffff6fa780d in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib64/libpthread.so.0
#1 0x0000000000b7a2f9 in uv_cond_wait (cond=<optimized out>,
---Type <return> to continue, or q <return> to quit---
mutex=<optimized out>) at ../deps/uv/src/unix/thread.c:324
#2 0x0000000000b6d35f in worker (arg=<optimized out>)
at ../deps/uv/src/threadpool.c:73
#3 0x0000000000b6dec1 in uv__thread_start (arg=<optimized out>)
at ../deps/uv/src/uv-common.c:278
#4 0x00007ffff6fa3f18 in start_thread () from /lib64/libpthread.so.0
#5 0x00007ffff6cd9b9d in clone () from /lib64/libc.so.6
Thread 3 (Thread 0x7ffff61e8700 (LWP 8353)):
#0 0x00007ffff6fa780d in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib64/libpthread.so.0
#1 0x0000000000b7a2f9 in uv_cond_wait (cond=<optimized out>,
mutex=<optimized out>) at ../deps/uv/src/unix/thread.c:324
#2 0x0000000000b6d35f in worker (arg=<optimized out>)
at ../deps/uv/src/threadpool.c:73
#3 0x0000000000b6dec1 in uv__thread_start (arg=<optimized out>)
at ../deps/uv/src/uv-common.c:278
#4 0x00007ffff6fa3f18 in start_thread () from /lib64/libpthread.so.0
#5 0x00007ffff6cd9b9d in clone () from /lib64/libc.so.6
Thread 2 (Thread 0x7ffff69e9700 (LWP 8352)):
#0 0x00007ffff6fa780d in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib64/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#1 0x0000000000b7a2f9 in uv_cond_wait (cond=<optimized out>,
mutex=<optimized out>) at ../deps/uv/src/unix/thread.c:324
#2 0x0000000000b6d35f in worker (arg=<optimized out>)
at ../deps/uv/src/threadpool.c:73
#3 0x0000000000b6dec1 in uv__thread_start (arg=<optimized out>)
at ../deps/uv/src/uv-common.c:278
#4 0x00007ffff6fa3f18 in start_thread () from /lib64/libpthread.so.0
#5 0x00007ffff6cd9b9d in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7ffff7fee740 (LWP 8348)):
#0 0x0000000000000000 in ?? ()
#1 0x00007ffff69eec0e in strongloop::agent::WakeUp::OnIdle(uv_idle_s*) ()
from /home/ec2-user/app/node_modules/strong-agent/build/Release/strong-agent.node
#2 0x0000000000b74af7 in uv__run_idle (loop=0x10b8500 <default_loop_struct>)
at ../deps/uv/src/unix/loop-watcher.c:63
#3 0x0000000000b6fe4b in uv_run (loop=0x10b8500 <default_loop_struct>,
mode=UV_RUN_ONCE) at ../deps/uv/src/unix/core.c:318
#4 0x0000000000b002d1 in node::Start(int, char**) ()
#5 0x00007ffff6c187d5 in __libc_start_main () from /lib64/libc.so.6
#6 0x00000000005fda09 in _start ()
(gdb)Is it possible that you originally used strong-agent with an older version of v0.11? Assuming you installed it with npm install strong-agent, can you:
$ rm -rf node_modules/
$ env V=1 npm_config_debug=1 npm install strong-agent
# please post the build log
$ gdb --args node server.js
# the `run` and `apply thread ...` thing againAlso:
node -p process.versions?jondubois
commented
10 years ago I created a new RedHat instance on EC2 (instead of the Amazon distro I was using earlier) and the problem persists.
It did work though when I installed the latest version of strong-agent using:
env V=1 npm_config_debug=1 npm install strong-agentThat said, when I run the top command while my node process is being profiled, the %CPU of that node process shows up as 99.9% and stays around that level even though the server is idle (same as what happened when I was using strong-agent v0.4.14).
node -p process.versions is:
{ http_parser: '2.3', node: '0.11.14', v8: '3.26.33', uv: '1.0.0', zlib: '1.2.3', modules: '14', openssl: '1.0.1i' }
bnoordhuis
commented
10 years ago Just to confirm, it's using 100% CPU when strong-agent is loaded? What's CPU consumption like without? Can you try the following? You may have to yum install perf first.
$ perf record -g -p $(pidof node)
# wait for about 30 seconds, then ^C
$ perf report -g flat --stdioCan you post the output of perf report here?
jondubois
commented
10 years ago Interesting. The perf report appears to be normal. I had the CPU monitoring off for the first 15 seconds and turned it on for the remaining 15 seconds and it didn't go up to 100% as the top command suggests. The numbers coming up on the StrongOps dashboard appear to be accurate. I guess the top command doesn't play nice with strong-agent?
Here's the perf:
captured on: Tue Oct 21 18:36:40 2014
hostname : ip-10-99-176-161
os release : 2.6.32-431.29.2.el6.x86_64
perf version : 2.6.32-431.29.2.el6.x86_64.debug
arch : x86_64
nrcpus online : 1
nrcpus avail : 1
cpudesc : Intel(R) Xeon(R) CPU E5-2670 v2 @ 2.50GHz
cpuid : GenuineIntel,6,62,4
total memory : 3729112 kB
cmdline : /usr/bin/perf record -g -p 1710
event : name = cpu-clock, type = 1, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 40, 41, 42, 43, 44 }
HEADER_CPU_TOPOLOGY info available, use -I to display
HEADER_NUMA_TOPOLOGY info available, use -I to display
pmu mappings: tracepoint = 2, software = 1
========
Samples: 114 of event 'cpu-clock'
Event count (approx.): 114
Overhead Command Shared Object Symbol
........ ....... ................. ......................................................................................................................................................................................................................................................
6.14% node node [.] v8::internal::HeapObjectIterator::Next()
6.14%
v8::internal::HeapObjectIterator::Next()
6.14% node node [.] v8::internal::FlexibleBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FixedArray::BodyDescriptor, void>::Visit(v8::internal::Map*, v8::internal::HeapObject*)
6.14%
v8::internal::FlexibleBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FixedArray::BodyDescriptor, void>::Visit(v8::internal::Map*, v8::internal::HeapObject*)
6.14% node node [.] void v8::internal::RelocInfo::Visit<v8::internal::MarkCompactMarkingVisitor>(v8::internal::Heap*)
6.14%
void v8::internal::RelocInfo::Visit<v8::internal::MarkCompactMarkingVisitor>(v8::internal::Heap*)
5.26% node [kernel.kallsyms] [k] finish_task_switch
5.26%
finish_task_switch
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
4.39% node node [.] v8::internal::RelocIterator::next()
4.39%
v8::internal::RelocIterator::next()
4.39% node node [.] _ZN2v88internalL14SweepPreciselyILNS0_12SweepingModeE0ELNS0_22SkipListRebuildingModeE1ELNS0_22FreeSpaceTreatmentModeE0EEEvPNS0_10PagedSpaceEPNS0_4PageEPNS0_13ObjectVisitorE.isra.259
4.39%
_ZN2v88internalL14SweepPreciselyILNS0_12SweepingModeE0ELNS0_22SkipListRebuildingModeE1ELNS0_22FreeSpaceTreatmentModeE0EEEvPNS0_10PagedSpaceEPNS0_4PageEPNS0_13ObjectVisitorE.isra.259
3.51% node node [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::MarkMapContents(v8::internal::Heap*, v8::internal::Map*)
3.51%
v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::MarkMapContents(v8::internal::Heap*, v8::internal::Map*)
3.51% node [kernel.kallsyms] [k] clear_page_c_e
2.63%
clear_page_c_e
v8::internal::SemiSpace::GrowTo(int)
v8::internal::NewSpace::Grow()
v8::internal::Heap::CheckNewSpaceExpansionCriteria()
v8::internal::MarkCompactCollector::EvacuateNewSpace()
v8::internal::MarkCompactCollector::EvacuateNewSpaceAndCandidates()
v8::internal::MarkCompactCollector::SweepSpaces()
v8::internal::MarkCompactCollector::CollectGarbage()
v8::internal::Heap::MarkCompact(v8::internal::GCTracer*)
v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GCTracer*, v8::GCCallbackFlags)
v8::internal::Heap::CollectGarbage(v8::internal::GarbageCollector, char const*, char const*, v8::GCCallbackFlags)
v8::internal::Heap::CollectAllGarbage(int, char const*, v8::GCCallbackFlags)
v8::internal::Logger::LogAccessorCallbacks()
v8::internal::CpuProfiler::StartProcessorIfNotStarted()
compat::CpuProfiler::StartCpuProfiling(v8::Isolate*, v8::Local<v8::String>)
strongloop::agent::profiler::StartCpuProfiling(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d0a5a16
0x2f9b2d0a57ad
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2cf24b25
0x2f9b2d099b70
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d09326d
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::internal::Runtime_Apply(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d02adcb
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2d052090
0x2f9b2cf1e715
0x2f9b2d092494
0x2f9b2d051ce4
0x2f9b2d051ace
0x2f9b2d02ca39
0x2f9b2d02c673
0x2f9b2d02bfb8
0x2f9b2cf1e715
0x2f9b2d0531cc
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d08e1e0
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
node::Parser::on_body(http_parser*, char const*, unsigned long)
http_parser_execute
node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d085af3
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d084b3e
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
_ZN4node12TLSCallbacks8ClearOutEv.part.36
node::TLSCallbacks::DoRead(uv_stream_s*, long, uv_buf_t const*, uv_handle_type)
uv__read
uv__stream_io
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88%
clear_page_c_e
v8::internal::MarkCompactCollector::MigrateObject(v8::internal::HeapObject*, v8::internal::HeapObject*, int, v8::internal::AllocationSpace)
v8::internal::MarkCompactCollector::DiscoverAndPromoteBlackObjectsOnPage(v8::internal::NewSpace*, v8::internal::NewSpacePage*)
v8::internal::MarkCompactCollector::EvacuateNewSpace()
v8::internal::MarkCompactCollector::EvacuateNewSpaceAndCandidates()
v8::internal::MarkCompactCollector::SweepSpaces()
v8::internal::MarkCompactCollector::CollectGarbage()
v8::internal::Heap::MarkCompact(v8::internal::GCTracer*)
v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GCTracer*, v8::GCCallbackFlags)
v8::internal::Heap::CollectGarbage(v8::internal::GarbageCollector, char const*, char const*, v8::GCCallbackFlags)
v8::internal::Heap::CollectAllGarbage(int, char const*, v8::GCCallbackFlags)
v8::internal::Logger::LogAccessorCallbacks()
v8::internal::CpuProfiler::StartProcessorIfNotStarted()
compat::CpuProfiler::StartCpuProfiling(v8::Isolate*, v8::Local<v8::String>)
strongloop::agent::profiler::StartCpuProfiling(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d0a5a16
0x2f9b2d0a57ad
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2cf24b25
0x2f9b2d099b70
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d09326d
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::internal::Runtime_Apply(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d02adcb
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2d052090
0x2f9b2cf1e715
0x2f9b2d092494
0x2f9b2d051ce4
0x2f9b2d051ace
0x2f9b2d02ca39
0x2f9b2d02c673
0x2f9b2d02bfb8
0x2f9b2cf1e715
0x2f9b2d0531cc
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d08e1e0
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
node::Parser::on_body(http_parser*, char const*, unsigned long)
http_parser_execute
node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d085af3
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d084b3e
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
_ZN4node12TLSCallbacks8ClearOutEv.part.36
node::TLSCallbacks::DoRead(uv_stream_s*, long, uv_buf_t const*, uv_handle_type)
uv__read
uv__stream_io
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
2.63% node node [.] v8::internal::MarkCompactCollector::EmptyMarkingDeque()
2.63%
v8::internal::MarkCompactCollector::EmptyMarkingDeque()
2.63% node node [.] v8::internal::MarkCompactCollector::RecordRelocSlot(v8::internal::RelocInfo*, v8::internal::Object*)
2.63%
v8::internal::MarkCompactCollector::RecordRelocSlot(v8::internal::RelocInfo*, v8::internal::Object*)
2.63% node node [.] v8::internal::MarkCompactCollector::ClearNonLiveReferences()
2.63%
v8::internal::MarkCompactCollector::ClearNonLiveReferences()
1.75% node node [.] v8::internal::HeapObject::SizeFromMap(v8::internal::Map*)
1.75%
v8::internal::HeapObject::SizeFromMap(v8::internal::Map*)
1.75% node node [.] v8::internal::Heap::MoveBlock(unsigned char*, unsigned char*, int)
1.75%
v8::internal::Heap::MoveBlock(unsigned char*, unsigned char*, int)
1.75% node node [.] v8::internal::Code::CopyFrom(v8::internal::CodeDesc const&)
1.75%
v8::internal::Code::CopyFrom(v8::internal::CodeDesc const&)
1.75% node libc-2.12.so [.] memchr
1.75%
memchr
1.75% node [kernel.kallsyms] [k] get_signal_to_deliver
1.75%
get_signal_to_deliver
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
1.75% node [kernel.kallsyms] [k] get_page_from_freelist
0.88%
get_page_from_freelist
v8::internal::CpuProfiler::StartProcessorIfNotStarted()
compat::CpuProfiler::StartCpuProfiling(v8::Isolate*, v8::Local<v8::String>)
strongloop::agent::profiler::StartCpuProfiling(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d0a5a16
0x2f9b2d0a57ad
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2cf24b25
0x2f9b2d099b70
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d09326d
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::internal::Runtime_Apply(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d02adcb
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2d052090
0x2f9b2cf1e715
0x2f9b2d092494
0x2f9b2d051ce4
0x2f9b2d051ace
0x2f9b2d02ca39
0x2f9b2d02c673
0x2f9b2d02bfb8
0x2f9b2cf1e715
0x2f9b2d0531cc
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d08e1e0
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
node::Parser::on_body(http_parser*, char const*, unsigned long)
http_parser_execute
node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d085af3
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d084b3e
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
_ZN4node12TLSCallbacks8ClearOutEv.part.36
node::TLSCallbacks::DoRead(uv_stream_s*, long, uv_buf_t const*, uv_handle_type)
uv__read
uv__stream_io
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88%
get_page_from_freelist
v8::internal::Heap::MoveBlock(unsigned char*, unsigned char*, int)
v8::internal::MarkCompactCollector::MigrateObject(v8::internal::HeapObject*, v8::internal::HeapObject*, int, v8::internal::AllocationSpace)
v8::internal::MarkCompactCollector::EvacuateLiveObjectsFromPage(v8::internal::Page*)
v8::internal::MarkCompactCollector::EvacuatePages()
v8::internal::MarkCompactCollector::EvacuateNewSpaceAndCandidates()
v8::internal::MarkCompactCollector::SweepSpaces()
v8::internal::MarkCompactCollector::CollectGarbage()
v8::internal::Heap::MarkCompact(v8::internal::GCTracer*)
v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GCTracer*, v8::GCCallbackFlags)
v8::internal::Heap::CollectGarbage(v8::internal::GarbageCollector, char const*, char const*, v8::GCCallbackFlags)
v8::internal::Heap::CollectAllGarbage(int, char const*, v8::GCCallbackFlags)
v8::internal::Logger::LogAccessorCallbacks()
v8::internal::CpuProfiler::StartProcessorIfNotStarted()
compat::CpuProfiler::StartCpuProfiling(v8::Isolate*, v8::Local<v8::String>)
strongloop::agent::profiler::StartCpuProfiling(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d0a5a16
0x2f9b2d0a57ad
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2cf24b25
0x2f9b2d099b70
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d09326d
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::internal::Runtime_Apply(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d02adcb
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2d052090
0x2f9b2cf1e715
0x2f9b2d092494
0x2f9b2d051ce4
0x2f9b2d051ace
0x2f9b2d02ca39
0x2f9b2d02c673
0x2f9b2d02bfb8
0x2f9b2cf1e715
0x2f9b2d0531cc
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d08e1e0
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
node::Parser::on_body(http_parser*, char const*, unsigned long)
http_parser_execute
node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d085af3
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d084b3e
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
_ZN4node12TLSCallbacks8ClearOutEv.part.36
node::TLSCallbacks::DoRead(uv_stream_s*, long, uv_buf_t const*, uv_handle_type)
uv__read
uv__stream_io
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
1.75% node [kernel.kallsyms] [k] _spin_unlock_irqrestore
1.75%
_spin_unlock_irqrestore
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node node [.] v8::internal::Heap::AdjustAmountOfExternalAllocatedMemory(long)
0.88%
v8::internal::Heap::AdjustAmountOfExternalAllocatedMemory(long)
0.88% node node [.] v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
0.88%
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
0.88% node node [.] v8::internal::InnerPointerToCodeCache::GcSafeFindCodeForInnerPointer(unsigned char*)
0.88%
v8::internal::InnerPointerToCodeCache::GcSafeFindCodeForInnerPointer(unsigned char*)
0.88% node node [.] v8::internal::HeapIterator::NextObject()
0.88%
v8::internal::HeapIterator::NextObject()
0.88% node node [.] v8::internal::LoadIC::UpdateCaches(v8::internal::LookupResult*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::String>)
0.88%
v8::internal::LoadIC::UpdateCaches(v8::internal::LookupResult*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::String>)
0.88% node node [.] v8::internal::Code::is_invalidated_weak_stub()
0.88%
v8::internal::Code::is_invalidated_weak_stub()
0.88% node node [.] v8::internal::Logger::LogCompiledFunctions()
0.88%
v8::internal::Logger::LogCompiledFunctions()
0.88% node node [.] v8::internal::ShortCircuitConsString(v8::internal::Object**)
0.88%
v8::internal::ShortCircuitConsString(v8::internal::Object**)
0.88% node node [.] v8::internal::PointersUpdatingVisitor::VisitPointer(v8::internal::Object**)
0.88%
v8::internal::PointersUpdatingVisitor::VisitPointer(v8::internal::Object**)
0.88% node node [.] v8::internal::FixedBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FixedBodyDescriptor<24, 40, 40>, void>::Visit(v8::internal::Map*, v8::internal::HeapObject*)
0.88%
v8::internal::FixedBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FixedBodyDescriptor<24, 40, 40>, void>::Visit(v8::internal::Map*, v8::internal::HeapObject*)
0.88% node node [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitCode(v8::internal::Map*, v8::internal::HeapObject*)
0.88%
v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitCode(v8::internal::Map*, v8::internal::HeapObject*)
0.88% node node [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitJSFunction(v8::internal::Map*, v8::internal::HeapObject*)
0.88%
v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitJSFunction(v8::internal::Map*, v8::internal::HeapObject*)
0.88% node node [.] _ZN2v88internalL14SweepPreciselyILNS0_12SweepingModeE0ELNS0_22SkipListRebuildingModeE0ELNS0_22FreeSpaceTreatmentModeE1EEEvPNS0_10PagedSpaceEPNS0_4PageEPNS0_13ObjectVisitorE.isra.257
0.88%
_ZN2v88internalL14SweepPreciselyILNS0_12SweepingModeE0ELNS0_22SkipListRebuildingModeE0ELNS0_22FreeSpaceTreatmentModeE1EEEvPNS0_10PagedSpaceEPNS0_4PageEPNS0_13ObjectVisitorE.isra.257
0.88% node node [.] v8::internal::MarkCompactCollector::MigrateObject(v8::internal::HeapObject*, v8::internal::HeapObject*, int, v8::internal::AllocationSpace)
0.88%
v8::internal::MarkCompactCollector::MigrateObject(v8::internal::HeapObject*, v8::internal::HeapObject*, int, v8::internal::AllocationSpace)
0.88% node node [.] v8::internal::MarkCompactCollector::DiscoverAndPromoteBlackObjectsOnPage(v8::internal::NewSpace*, v8::internal::NewSpacePage*)
0.88%
v8::internal::MarkCompactCollector::DiscoverAndPromoteBlackObjectsOnPage(v8::internal::NewSpace*, v8::internal::NewSpacePage*)
0.88% node node [.] v8::internal::MarkCompactCollector::ClearNonLiveDependentCodeInGroup(v8::internal::DependentCode*, int, int, int, int)
0.88%
v8::internal::MarkCompactCollector::ClearNonLiveDependentCodeInGroup(v8::internal::DependentCode*, int, int, int, int)
0.88% node node [.] v8::internal::MarkCompactCollector::EvacuateNewSpaceAndCandidates()
0.88%
v8::internal::MarkCompactCollector::EvacuateNewSpaceAndCandidates()
0.88% node node [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitSharedFunctionInfoStrongCode(v8::internal::Heap*, v8::internal::HeapObject*)
0.88%
v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitSharedFunctionInfoStrongCode(v8::internal::Heap*, v8::internal::HeapObject*)
0.88% node node [.] void v8::internal::Code::CodeIterateBody<v8::internal::MarkCompactMarkingVisitor>(v8::internal::Heap*)
0.88%
void v8::internal::Code::CodeIterateBody<v8::internal::MarkCompactMarkingVisitor>(v8::internal::Heap*)
0.88% node node [.] v8::internal::HeapObject::IterateBody(v8::internal::InstanceType, int, v8::internal::ObjectVisitor*)
0.88%
v8::internal::HeapObject::IterateBody(v8::internal::InstanceType, int, v8::internal::ObjectVisitor*)
0.88% node node [.] v8::internal::SharedFunctionInfo::ClearTypeFeedbackInfo()
0.88%
v8::internal::SharedFunctionInfo::ClearTypeFeedbackInfo()
0.88% node node [.] v8::internal::Map::AddDependentIC(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Code>)
0.88%
v8::internal::Map::AddDependentIC(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Code>)
0.88% node node [.] v8::internal::String::ToCString(v8::internal::AllowNullsFlag, v8::internal::RobustnessFlag, int, int, int*)
0.88%
v8::internal::String::ToCString(v8::internal::AllowNullsFlag, v8::internal::RobustnessFlag, int, int, int*)
0.88% node node [.] v8::internal::String::CalculateLineEnds(v8::internal::Handle<v8::internal::String>, bool)
0.88%
v8::internal::String::CalculateLineEnds(v8::internal::Handle<v8::internal::String>, bool)
0.88% node node [.] v8::internal::Runtime::SetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, PropertyAttributes, v8::internal::StrictMode)
0.88%
v8::internal::Runtime::SetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, PropertyAttributes, v8::internal::StrictMode)
0.88% node node [.] v8::internal::SignalHandler::HandleProfilerSignal(int, siginfo*, void*)
0.88%
v8::internal::SignalHandler::HandleProfilerSignal(int, siginfo*, void*)
0.88% node node [.] v8::internal::Scope::ResolveVariable(v8::internal::CompilationInfo*, v8::internal::VariableProxy*, v8::internal::AstNodeFactory<v8::internal::AstNullVisitor>*)
0.88%
v8::internal::Scope::ResolveVariable(v8::internal::CompilationInfo*, v8::internal::VariableProxy*, v8::internal::AstNodeFactory<v8::internal::AstNullVisitor>*)
0.88% node node [.] v8::internal::PagedSpace::CountTotalPages()
0.88%
v8::internal::PagedSpace::CountTotalPages()
0.88% node node [.] v8::internal::StoreBuffer::IteratePointersInStoreBuffer(void (*)(v8::internal::HeapObject**, v8::internal::HeapObject*), bool)
0.88%
v8::internal::StoreBuffer::IteratePointersInStoreBuffer(void (*)(v8::internal::HeapObject**, v8::internal::HeapObject*), bool)
0.88% node node [.] v8::internal::CPU::FlushICache(void*, unsigned long)
0.88%
v8::internal::CPU::FlushICache(void*, unsigned long)
0.88% node node [.] v8::internal::LGapResolver::EmitMove(int)
0.88%
v8::internal::LGapResolver::EmitMove(int)
0.88% node node [.] uv__io_poll
0.88%
uv__io_poll
0.88% node libc-2.12.so [.] _int_malloc
0.88%
_int_malloc
0.88% node libc-2.12.so [.] malloc
0.88%
malloc
0.88% node libc-2.12.so [.] syscall
0.88%
syscall
0.88% node libc-2.12.so [.] __memcmp_sse4_1
0.88%
__memcmp_sse4_1
0.88% node [vsyscall] [.] 0x0000000000000140
0.88%
0xffffffffff600140
0.88% node [kernel.kallsyms] [k] native_read_tsc
0.88%
native_read_tsc
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] restore_i387_xstate
0.88%
restore_i387_xstate
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] syscall_trace_leave
0.88%
syscall_trace_leave
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] __audit_syscall_exit
0.88%
__audit_syscall_exit
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] __alloc_pages_nodemask
0.88%
__alloc_pages_nodemask
v8::internal::Heap::MoveBlock(unsigned char*, unsigned char*, int)
v8::internal::MarkCompactCollector::MigrateObject(v8::internal::HeapObject*, v8::internal::HeapObject*, int, v8::internal::AllocationSpace)
v8::internal::MarkCompactCollector::DiscoverAndPromoteBlackObjectsOnPage(v8::internal::NewSpace*, v8::internal::NewSpacePage*)
v8::internal::MarkCompactCollector::EvacuateNewSpace()
v8::internal::MarkCompactCollector::EvacuateNewSpaceAndCandidates()
v8::internal::MarkCompactCollector::SweepSpaces()
v8::internal::MarkCompactCollector::CollectGarbage()
v8::internal::Heap::MarkCompact(v8::internal::GCTracer*)
v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GCTracer*, v8::GCCallbackFlags)
v8::internal::Heap::CollectGarbage(v8::internal::GarbageCollector, char const*, char const*, v8::GCCallbackFlags)
v8::internal::Heap::CollectAllGarbage(int, char const*, v8::GCCallbackFlags)
v8::internal::Logger::LogCompiledFunctions()
v8::internal::CpuProfiler::StartProcessorIfNotStarted()
compat::CpuProfiler::StartCpuProfiling(v8::Isolate*, v8::Local<v8::String>)
strongloop::agent::profiler::StartCpuProfiling(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d0a5a16
0x2f9b2d0a57ad
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2cf24b25
0x2f9b2d099b70
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d09326d
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::internal::Runtime_Apply(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d02adcb
0x2f9b2cf1e715
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2d052090
0x2f9b2cf1e715
0x2f9b2d092494
0x2f9b2d051ce4
0x2f9b2d051ace
0x2f9b2d02ca39
0x2f9b2d02c673
0x2f9b2d02bfb8
0x2f9b2cf1e715
0x2f9b2d0531cc
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d08e1e0
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
node::Parser::on_body(http_parser*, char const*, unsigned long)
http_parser_execute
node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
0x2f9b2cf060a2
0x2f9b2d085af3
0x2f9b2cf63484
0x2f9b2cf1e715
0x2f9b2d052867
0x2f9b2d0522f1
0x2f9b2cf1e715
0x2f9b2d084b3e
0x2f9b2cf1ef60
0x2f9b2cf1dd50
v8::internal::Invoke(bool, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
v8::Function::Call(v8::Handle<v8::Value>, int, v8::Handle<v8::Value>*)
_ZN4node12TLSCallbacks8ClearOutEv.part.36
node::TLSCallbacks::DoRead(uv_stream_s*, long, uv_buf_t const*, uv_handle_type)
uv__read
uv__stream_io
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] sys_mmap_pgoff
0.88%
sys_mmap_pgoff
__GI___mmap64
0.88% node [kernel.kallsyms] [k] fget
0.88%
fget
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] fput
0.88%
fput
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
0.88% node [kernel.kallsyms] [k] schedule_hrtimeout_range
0.88%
schedule_hrtimeout_range
syscall
uv__io_poll
uv_run
node::Start(int, char**)
__libc_start_main
(For a higher level overview, try: perf report --sort comm,dso)That looks pretty normal, and yes, top can be quite the CPU hog. Its basic mode of operation consists of polling lots of /proc files in a loop.
jondubois
commented
10 years ago I'm still getting the performance issue - I don't know why it's showing up again. Usage according to StrongOps is 80% which doesn't sound right. Here's the perf log (this is on an idle Node.js process):
To display the perf.data header info, please use --header/--header-only options.
Samples: 3K of event 'cpu-clock' Event count (approx.): 3189
Overhead Command Shared Object Symbol ........ ....... .................. .............................................................
26.78% node [kernel.kallsyms] [k] hypercall_page
26.47%
hypercall_page
check_events
0x7fff5f7ffa1f
16.81% node [vdso] [.] 0x0000000000000a1f
16.81%
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
7.96% node [kernel.kallsyms] [k] audit_syscall_entry
6.08%
audit_syscall_entry
auditsys
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.79%
audit_syscall_entry
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
4.95% node [kernel.kallsyms] [k] sys_clock_gettime
3.45%
sys_clock_gettime
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.85%
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.63%
sys_clock_gettime
0x7fff5f7ffa1f
4.74% node [kernel.kallsyms] [k] pvclock_clocksource_read
3.45%
pvclock_clocksource_read
xen_clocksource_read
xen_clocksource_get_cycles
ktime_get_ts
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.29%
pvclock_clocksource_read
xen_clocksource_get_cycles
ktime_get_ts
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
4.70% node [kernel.kallsyms] [k] current_kernel_time
2.82%
current_kernel_time
audit_syscall_entry
auditsys
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.88%
current_kernel_time
auditsys
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
3.48% node [kernel.kallsyms] [k] ktime_get_ts
1.79%
ktime_get_ts
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.69%
ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
2.45% node [kernel.kallsyms] [k] dput
1.85%
dput
audit_syscall_exit
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.60%
dput
path_put
audit_syscall_exit
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
2.41% node [kernel.kallsyms] [k] audit_syscall_exit
1.25%
audit_syscall_exit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.10%
audit_syscall_exit
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
2.32% node node [.] v8::internal::ProfilerEventsProcessor::ProcessOneSample()
2.29%
v8::internal::ProfilerEventsProcessor::ProcessOneSample()
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
2.26% node [kernel.kallsyms] [k] posix_ktime_get_ts
2.20%
posix_ktime_get_ts
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.91% node [kernel.kallsyms] [k] _copy_to_user
1.91%
_copy_to_user
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.79% node [kernel.kallsyms] [k] unroll_tree_refs
1.10%
unroll_tree_refs
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.69%
unroll_tree_refs
audit_syscall_exit
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.72% node [kernel.kallsyms] [k] system_call_after_swapgs
1.72%
system_call_after_swapgs
0x7fff5f7ffa1f
1.69% node [kernel.kallsyms] [k] native_read_tsc
1.13%
native_read_tsc
xen_clocksource_read
xen_clocksource_get_cycles
ktime_get_ts
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.56%
native_read_tsc
pvclock_clocksource_read
xen_clocksource_read
xen_clocksource_get_cycles
ktime_get_ts
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.60% node [kernel.kallsyms] [k] path_put
1.51%
path_put
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.54% node [kernel.kallsyms] [k] xen_irq_enable_direct
1.54%
xen_irq_enable_direct
0x7fff5f7ffa1f
1.47% node [kernel.kallsyms] [k] copy_user_generic_string
1.47%
copy_user_generic_string
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.44% node [kernel.kallsyms] [k] set_normalized_timespec
1.16%
set_normalized_timespec
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.25% node [kernel.kallsyms] [k] kfree
1.07%
kfree
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.16% node node [.] v8::internal::TimeTicks::HighResolutionNow()
0.69%
v8::internal::TimeTicks::HighResolutionNow()
v8::internal::ThreadEntry(void*)
start_thread
0.47%
v8::internal::TimeTicks::HighResolutionNow()
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.07% node [kernel.kallsyms] [k] xen_clocksource_read
0.97%
xen_clocksource_read
xen_clocksource_get_cycles
ktime_get_ts
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
1.03% node [kernel.kallsyms] [k] xen_clocksource_get_cycles
1.03%
xen_clocksource_get_cycles
posix_ktime_get_ts
sys_clock_gettime
system_call_fastpath
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.78% node [kernel.kallsyms] [k] mntput
0.75%
mntput
audit_syscall_exit
sysret_audit
0x7fff5f7ffa1f
clock_gettime
v8::internal::ProfilerEventsProcessor::Run()
v8::internal::ThreadEntry(void*)
start_thread
0.60% node [kernel.kallsyms] [k] tracesys
0.60%
tracesys
0x7fff5f7ffa1f
0.38% node libc-2.17.so [.] clock_gettime
0.34% node [kernel.kallsyms] [k] sysret_audit
0.25% node [vdso] [.] 0x0000000000000a20
0.22% node [kernel.kallsyms] [k] auditsys
0.16% node node [.] v8::internal::ProfilerEventsProcessor::Run()
0.16% node [kernel.kallsyms] [k] system_call_fastpath
0.13% node [kernel.kallsyms] [k] sysret_check
0.06% node [kernel.kallsyms] [k] ret_from_sys_call
0.06% node [kernel.kallsyms] [k] sysret_signal
0.03% node libpthread-2.17.so [.] pthread_kill
0.03% node [vdso] [.] 0x0000000000000a00
0.03% node [vdso] [.] 0x0000000000000a15
0.03% node [kernel.kallsyms] [k] xen_irq_enable_direct_end
0.03% node [kernel.kallsyms] [k] xen_irq_disable_direct
0.03% node [kernel.kallsyms] [k] syscall_trace_leave
0.03% node [kernel.kallsyms] [k] __lock_task_sighand
0.03% node [kernel.kallsyms] [k] sys_tgkill
0.03% node [kernel.kallsyms] [k] security_task_kill
0.03% node [kernel.kallsyms] [k] schedule (For a higher level overview, try: perf report --sort comm,dso)
bnoordhuis
commented
10 years ago @jondubois The call graphs suggest that the CPU profiler is running. It's not so much the CPU profiler that is the cost center here but the fact that it queries the kernel for the current time, something that is an expensive operation on most virtualized systems.
If your node version is <= v0.10.26 you should consider upgrading. I added a workaround in joyent/node@f9ced08 but it requires that the kernel is compiled with CONFIG_HZ_1000. Most distro kernels are but check grep CONFIG_HZ /lib/modules/$(uname -r)/build/.config (the exact location depends on the distro) if unsure.
jondubois
commented
10 years ago I'm using Node.js v0.11.14. Running on an EC2 instance - I tried running on both the Amazon distro and RedHat and I get the same issue. The command you provided produced no output on my system. When I entered grep CONFIG_HZ /boot/config* I got:
/boot/config-2.6.35.14-97.44.amzn1.x86_64:# CONFIG_HZ_100 is not set /boot/config-2.6.35.14-97.44.amzn1.x86_64:# CONFIG_HZ_250 is not set /boot/config-2.6.35.14-97.44.amzn1.x86_64:# CONFIG_HZ_300 is not set /boot/config-2.6.35.14-97.44.amzn1.x86_64:CONFIG_HZ_1000=y /boot/config-2.6.35.14-97.44.amzn1.x86_64:CONFIG_HZ=1000 /boot/config-3.2.21-1.32.6.amzn1.x86_64:# CONFIG_HZ_100 is not set /boot/config-3.2.21-1.32.6.amzn1.x86_64:# CONFIG_HZ_250 is not set /boot/config-3.2.21-1.32.6.amzn1.x86_64:# CONFIG_HZ_300 is not set /boot/config-3.2.21-1.32.6.amzn1.x86_64:CONFIG_HZ_1000=y /boot/config-3.2.21-1.32.6.amzn1.x86_64:CONFIG_HZ=1000
bnoordhuis
commented
10 years ago The v0.11 series don't contain the fix, I haven't forward-ported it yet.
sam-github
commented
10 years ago So, summary @jondubois, is
jondubois
commented
10 years ago @sam-github, the seg fault happened when I installed strong-agent using:
npm install strong-agentInstalling it using:
env V=1 npm_config_debug=1 npm install strong-agentTook care of the seg fault.
So now the only issue remaining is that strong-agent appears to be using a lot of CPU. It reports an idle process as using around 75% of the total CPU (but it should really be approaching 0% since it's idle - Running it without strong-agent profiling confirms this theory). Could the command I used to install strong-agent (with config_debug=1) be the cause of this issue?
I'll wait for the fix to be forward ported.
bnoordhuis
commented
10 years ago @jondubois The debug build is compiled at -O0 so yes, it will be slower. The difference is not normally noticeable unless you use the heapdiff component, the page on the dashboard that graphs the makeup of the JS heap over time.
If with node.js v0.10, you still get the segfault with release builds of the latest strong-agent, please post the stack trace and I'll take a look. The easiest way to get one is to turn on core dumps (ulimit -c unlimited), then after the crash:
$ gdb /path/to/node /path/to/corefile
> thread apply all backtrace(I mention node.js v0.10 explicitly because the last couple of v0.11 releases have known bugs.)
bnoordhuis
commented
9 years ago Got an email from Jon:
On Mon, Nov 24, 2014 at 11:42 AM, Jonathan Gros-Dubois <[elided]> wrote:
Hi Ben,
This is a follow up on this issue: https://github.com/strongloop/strong-agent/issues/3 I managed to find some time to try strong-agent again on Node v0.10.
The segmentation faults are no longer occurring :) But strong-agent still appears to be using up a massive amount of CPU. I know we've been back and forth on that issue a bit, but I don't think I expressed the extent of the problem correctly so I created an account on a new Amazon instance so you can test it yourself.
Here are the SSH details (requires password auth):
host: [elided] username: [elided] password: [elided]
Once logged in:
- Navigate to the test/ directory
- vim server.js
- Change agent.profile(...) call to connect to your StrongOps dashboard
- node server.js
- Go to strongOps CPU profiler and start profiling
- Wait a few minutes
- Go to dashboard and check how much CPU it's using
On my machine it reports close to 100% (mostly 'user')
The Node.js server is idle so I don't understand why it's using so much CPU
Anyway, let me know how it goes.
Cheers, Jon
Jon, what you are seeing is not unexpected. The CPU profiler wakes up 1,000/second to record a sample (including when the process itself is sleeping) and that's in aggregate reasonably expensive.
It's not designed to be kept running indefinitely; you normally turn it on for 5 to 30 seconds to get some quick insights into what your application is doing. I'm not sure what our documentation says about it, but perhaps we need to be more explicit about that caveat (/cc @crandmck.)
The next strong-agent release will have a watchdog mode where the profiler is automatically activated and deactivated when a script is taking too long to execute (paid feature, however.)
I'm probably going to extend it so that it suspends the profiler when the process is sleeping. That would let you run the profiler for longer periods of time without undue overhead.
jondubois
commented
9 years ago I see. I was hoping I could use it as a long-running CPU monitoring + reporting tool but it appears to be intended for short-term debugging. I guess Strongloop doesn't offer any such tool (for tracking CPU use over time)?
In any case, thanks for your time and patience :)
bnoordhuis
commented
9 years ago I guess Strongloop doesn't offer any such tool (for tracking CPU use over time)?
Not yet / not quite. We can track aggregate CPU usage (what time(1) reports as user time) but while that is basically free, it doesn't tell you where your program spends its time. You need sample-based profiling for that but that has unavoidable overhead.
I've been experimenting with adjusting the sample frequency to reduce overhead while still retaining enough granularity to extract meaningful data, e.g. sampling at 333 Hz instead of 1000 Hz. It definitely lowers the overhead but it's not clear yet where the sweet spot is; maybe there isn't one and the frequency needs to be configurable or dynamic.
Longer term, we may start instrumenting V8's generated machine code with RDTSC (Read Timestamp Counter) instructions at function entry/exit and loop edges, although there are some caveats:
bnoordhuis
commented
9 years ago @jondubois If you're willing to be a guinea pig, please give bnoordhuis/node@24852b5 a try. On my EC2 box, it reduces the overhead from the CPU profiler by about 50%.
crandmck
commented
9 years ago I added a note to the docs stating that CPU profiling is not meant to run indefinitely.
jondubois
commented
9 years ago I will try running it using your patch sometime this week when I can find the time. Thanks.
I'm running Node.js v0.11.14
I have a custom multi-process Node.js deployment and I want to track each process PID under a common app name. I couldn't get it working with strong-agent version >= 1.0.0 - It launches properly (the correct app name and PID show up on StrongOps) but I get a segmentation fault as soon as I turn on the CPU profiler from StrongOps.
This error happens regardless of what process I'm trying to track - I created a really basic Node.js server and the segmentation fault still happens (so it's not related to my specific project).
Note that everything works fine if I launch using:
Unfortunately, this is not possible in my case since I have a custom multi-process architecture involving sticky load-balancer, worker and data-store processes.
So I would like to be able to run my app using:
and then use:
to track my metrics.
I did manage to get it working (kind of) using strong-agent version 0.4.14 (it doesn't crash with a seg fault) but when I check my CPU load using the top command (while my app is running with strong-agent), it shows that the process which I am monitoring is always using approx 100% of CPU even when it should in fact be idle - I tested with and without strong-agent and I can confirm that the CPU approaches 0% when strong-agent is not running. It looks like strong-agent is adding a lot of CPU overhead when it's running (maybe this is a bug with version 0.4.14).
Using v0.4.14 I can see graphs come up in StrongOps but they report very high CPU usage with a baseline of around 80% which is not accurate.