Profiling chimera-framework

chimera-framework-profiling.md

1. Make sure you have mongodb, gcc, python & nodejs installed
2. Clone chimera-framework (git clone [email protected]:goFrendiAsgard/chimera-framework.git)
3. Go to chimera-framework directory (cd chimera-framework)
4. Perform npm test to make sure everything is working.
5. Perform node --prof node_modules/mocha/bin/_mocha
6. A profile log file will be produced. In my case, the name of the file is isolate-0x2652d80-v8.log.
7. Make a more readable log file by performing node --prof-process isolate-0x2652d80-v8.log > profile.log.
8. Open up profile.log with your favorite text editor

I can't post the full log file because it is to big, but here is the overview:

Statistical profiling result from isolate-0x2652d80-v8.log, (2077 ticks, 139 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
    658   31.7%          /usr/bin/node
     37    1.8%          /lib/x86_64-linux-gnu/libc-2.27.so
      1    0.0%          [vdso]
      1    0.0%          /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25

 [JavaScript]:
   ticks  total  nonlib   name
     52    2.5%    3.8%  Builtin: InterpreterEntryTrampoline
     17    0.8%    1.2%  Stub: StringAddStub
     16    0.8%    1.2%  Builtin: CallFunction_ReceiverIsAny
     14    0.7%    1.0%  StoreIC: A store IC from the snapshot
      9    0.4%    0.7%  Builtin: KeyedLoadIC_Megamorphic
      8    0.4%    0.6%  LazyCompile: ~formatValue util.js:392:21
      7    0.3%    0.5%  Builtin: LoadIC_Noninlined
      7    0.3%    0.5%  Builtin: Call_ReceiverIsAny
      6    0.3%    0.4%  KeyedLoadIC: A keyed load IC from the snapshot
      5    0.2%    0.4%  Builtin: RegExpPrototypeTest
      5    0.2%    0.4%  Builtin: KeyedStoreIC_Megamorphic_Strict
      4    0.2%    0.3%  Stub: GetPropertyStub
      4    0.2%    0.3%  LazyCompile: ~Module._load module.js:448:24
      4    0.2%    0.3%  Builtin: StringPrototypeCharCodeAt
      4    0.2%    0.3%  Builtin: Call_ReceiverIsNullOrUndefined
      4    0.2%    0.3%  Builtin: ArrayIndexOf
      3    0.1%    0.2%  LazyCompile: ~serializeInto /home/gofrendi/Projects/chimera-framework/node_modules/bson/lib/bson/parser/serializer.js:671:43
      3    0.1%    0.2%  LazyCompile: ~parse url.js:101:37
      3    0.1%    0.2%  LazyCompile: ~makeRequireFunction internal/module.js:5:29
      3    0.1%    0.2%  LazyCompile: ~getFilteredObject /home/gofrendi/Projects/chimera-framework/lib/util.js:35:28
      3    0.1%    0.2%  LazyCompile: ~getChainWithTrueMode /home/gofrendi/Projects/chimera-framework/lib/core-preprocessor.js:102:33
      3    0.1%    0.2%  LazyCompile: ~format util.js:182:16
      3    0.1%    0.2%  LazyCompile: ~_clone /home/gofrendi/Projects/chimera-framework/node_modules/clone/clone.js:73:18
      ...
 [C++]:
   ticks  total  nonlib   name
    123    5.9%    8.9%  syscall
     26    1.3%    1.9%  v8::internal::IncrementalMarking::Step(unsigned long, v8::internal::IncrementalMarking::CompletionAction, v8::internal::IncrementalMarking::ForceCompletionAction, v8::internal::StepOrigin)
     12    0.6%    0.9%  v8::internal::Scanner::Scan()
     11    0.5%    0.8%  void v8::internal::BodyDescriptorBase::IteratePointers<v8::internal::IncrementalMarkingMarkingVisitor>(v8::internal::HeapObject*, int, int, v8::internal::IncrementalMarkingMarkingVisitor*)
     11    0.5%    0.8%  v8::internal::Scanner::ScanIdentifierOrKeyword()
     11    0.5%    0.8%  v8::internal::IncrementalMarking::WhiteToGreyAndPush(v8::internal::HeapObject*)
     10    0.5%    0.7%  v8::internal::Zone::New(unsigned long)
     10    0.5%    0.7%  v8::internal::Scavenger::ScavengeObject(v8::internal::HeapObject**, v8::internal::HeapObject*)
     10    0.5%    0.7%  v8::internal::Scanner::Next()
     10    0.5%    0.7%  int v8::internal::BinarySearch<(v8::internal::SearchMode)1, v8::internal::DescriptorArray>(v8::internal::DescriptorArray*, v8::internal::Name*, int, int*)
     10    0.5%    0.7%  cfree
      9    0.4%    0.7%  v8::internal::String::ComputeAndSetHash()
      9    0.4%    0.7%  node::HandleWrap::Close(v8::FunctionCallbackInfo<v8::Value> const&)
      8    0.4%    0.6%  void node::StreamBase::JSMethod<node::LibuvStreamWrap, &(int node::StreamBase::WriteString<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&))>(v8::FunctionCallbackInfo<v8::Value> const&)
      7    0.3%    0.5%  void v8::internal::String::WriteToFlat<unsigned char>(v8::internal::String*, unsigned char*, int, int)
      7    0.3%    0.5%  v8::internal::InterpretedFrame::Summarize(std::vector<v8::internal::FrameSummary, std::allocator<v8::internal::FrameSummary> >*, v8::internal::FrameSummary::Mode) const
      ...

 [Summary]:
   ticks  total  nonlib   name
    423   20.4%   30.7%  JavaScript
    818   39.4%   59.3%  C++
    102    4.9%    7.4%  GC
    697   33.6%          Shared libraries
    139    6.7%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
    628   51.1%   30.2%  v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
    208   16.9%   10.0%  v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*)
     55    4.5%    2.6%  v8::internal::Runtime_ThrowCalledNonCallable(int, v8::internal::Object**, v8::internal::Isolate*)
     49    4.0%    2.4%  v8::internal::Builtin_JsonParse(int, v8::internal::Object**, v8::internal::Isolate*)
     36    2.9%    1.7%  v8::internal::Runtime_StoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
     26    2.1%    1.3%  v8::internal::Runtime_LoadIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
     21    1.7%    1.0%  v8::internal::Builtin_FunctionConstructor(int, v8::internal::Object**, v8::internal::Isolate*)
     20    1.6%    1.0%  v8::internal::Runtime_KeyedGetProperty(int, v8::internal::Object**, v8::internal::Isolate*)
    ...

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
    658   31.7%  /usr/bin/node
    598   90.9%    v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
    261   43.6%      LazyCompile: ~createScript vm.js:79:22
    254   97.3%        LazyCompile: ~runInThisContext vm.js:138:26
    254  100.0%          LazyCompile: ~Module._compile module.js:609:37
    254  100.0%            LazyCompile: ~Module._extensions..js module.js:661:37
      7    2.7%        LazyCompile: ~runInNewContext vm.js:123:25
      7  100.0%          LazyCompile: ~safeEval /home/gofrendi/Projects/chimera-framework/lib/safe-eval.js:4:36
      7  100.0%            LazyCompile: ~evaluateStatement /home/gofrendi/Projects/chimera-framework/lib/core.js:177:30
     95   15.9%      LazyCompile: *createScript vm.js:79:22
     94   98.9%        LazyCompile: ~runInThisContext vm.js:138:26
     94  100.0%          LazyCompile: ~Module._compile module.js:609:37
     94  100.0%            LazyCompile: ~Module._extensions..js module.js:661:37
      1    1.1%        LazyCompile: ~runInNewContext vm.js:123:25
      1  100.0%          LazyCompile: ~safeEval /home/gofrendi/Projects/chimera-framework/lib/safe-eval.js:4:36
      1  100.0%            LazyCompile: *evaluateStatement /home/gofrendi/Projects/chimera-framework/lib/core.js:177:30
      ....