Profiling problem, is 91% of ticks in libc 'normal'.

Showing 1-5 of 5 messages
Profiling problem, is 91% of ticks in libc 'normal'. Chris Dew 10/4/12 9:23 AM
I'm starting to have a speed problem with a production NodeJS application (20-100% cpu usage).  

I've run it with --prof and used node-tick-processor.

Is 91% of ticks in libc 'normal'?

Thanks,

Chris.

P.S. is there a way to show the 'unaccounted' ticks?  I expect it needs to be told where to find the source of the app.


Statistical profiling result from node, (121509 ticks, 7342 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
   7342    6.0%

 [Shared libraries]:
   ticks  total  nonlib   name
  111345   91.6%    0.0%  /lib/libc-2.12.1.so
    248    0.2%    0.0%  /lib/libpthread-2.12.1.so
     19    0.0%    0.0%  /lib/libm-2.12.1.so
     19    0.0%    0.0%  /lib/libcrypto.so.0.9.8
      2    0.0%    0.0%  ffffffffff600000-ffffffffff601000
      2    0.0%    0.0%  7fff735ff000-7fff73600000
      1    0.0%    0.0%  /usr/lib/libstdc++.so.6.0.14
      1    0.0%    0.0%  /lib/libssl.so.0.9.8

 [JavaScript]:
   ticks  total  nonlib   name
   1628    1.3%   16.5%  LazyCompile: *Socket._write net.js:470
   1391    1.1%   14.1%  LazyCompile: *parse native json.js:55
   1196    1.0%   12.1%  LazyCompile: ~BasicSerializeObject native json.js:244
    372    0.3%    3.8%  LazyCompile: stringify native json.js:307
    280    0.2%    2.8%  LazyCompile: FILTER_KEY native runtime.js:399
    266    0.2%    2.7%  LazyCompile: TxnInPeriodLRS.getResultSet /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/txnInPeriodLRS.js:35
    260    0.2%    2.6%  LazyCompile: *formatProperty util.js:298
    221    0.2%    2.2%  Function: formatValue util.js:153
    208    0.2%    2.1%  Function: formatPrimitive util.js:249
    206    0.2%    2.1%  LazyCompile: *GetOwnProperty native v8natives.js:649
    138    0.1%    1.4%  LazyCompile: *indexOf native string.js:115
    118    0.1%    1.2%  LazyCompile: Join native array.js:119
    112    0.1%    1.1%  Stub: CEntryStub
    107    0.1%    1.1%  LazyCompile: *FromPropertyDescriptor native v8natives.js:385
    103    0.1%    1.0%  LazyCompile: *keys native v8natives.js:347
     88    0.1%    0.9%  LazyCompile: *BasicSerializeArray native json.js:181
     86    0.1%    0.9%  LazyCompile: ConvertDescriptorArrayToDescriptor native v8natives.js:593
     86    0.1%    0.9%  Function: ~Buffer buffer.js:210
     82    0.1%    0.8%  LazyCompile: PropertyDescriptor native v8natives.js:494
     81    0.1%    0.8%  LazyCompile: *EventEmitter.emit events.js:40
     79    0.1%    0.8%  Function: ~Buffer.write buffer.js:323
     72    0.1%    0.7%  Function: ~EventEmitter.emit events.js:40
     62    0.1%    0.6%  Stub: StringAddStub {3}
     60    0.0%    0.6%  LazyCompile: resultDelta /home/chris/CDRReportServer/tags/1.1.0/common/levenshtein/lib/resultdelta.js:7
     60    0.0%    0.6%  LazyCompile: *RegExpExecNoTests native regexp.js:156
     56    0.0%    0.6%  LazyCompile: *indexOf native array.js:1122
     50    0.0%    0.5%  Stub: NumberToStringStub
     49    0.0%    0.5%  KeyedLoadIC: A keyed load IC from the snapshot
     49    0.0%    0.5%  Function: exports.format util.js:23
     45    0.0%    0.5%  LazyCompile: *map native array.js:1094
     39    0.0%    0.4%  LazyCompile: *BuildResultFromMatchInfo native regexp.js:126
     39    0.0%    0.4%  Builtin: A builtin from the snapshot {2}
     38    0.0%    0.4%  Stub: CompareICStub {3}
     38    0.0%    0.4%  Function: ~ondata stream.js:36
     38    0.0%    0.4%  Builtin: A builtin from the snapshot {3}
     37    0.0%    0.4%  LazyCompile: *match native string.js:179
     36    0.0%    0.4%  Stub: RegExpExecStub
     33    0.0%    0.3%  LazyCompile: hasOwnProperty native v8natives.js:264
     29    0.0%    0.3%  Stub: CompareStub
     27    0.0%    0.3%  LazyCompile: ~keys native v8natives.js:347
     25    0.0%    0.3%  Stub: ToBooleanStub
     24    0.0%    0.2%  LazyCompile: VirtualLRS.checkDups /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualLRS.js:219
     24    0.0%    0.2%  LazyCompile: ToString native runtime.js:560
     23    0.0%    0.2%  Stub: SubStringStub
     23    0.0%    0.2%  Builtin: A builtin from the snapshot
     22    0.0%    0.2%  LazyCompile: *isRegExp util.js:387
     21    0.0%    0.2%  LazyCompile: *formatArray util.js:278
     21    0.0%    0.2%  LazyCompile: *VirtualAggregatingLRS.onInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualAggregatingLRS.js:53
     20    0.0%    0.2%  LazyCompile: ~parse native json.js:55
     20    0.0%    0.2%  LazyCompile: ~join native array.js:399
     20    0.0%    0.2%  LazyCompile: MdipSuccessesInPeriodLRS.getResultSet /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/mdipSuccessesInPeriodLRS.js:45
     20    0.0%    0.2%  LazyCompile: *isError util.js:399
     20    0.0%    0.2%  LazyCompile: *LocalConnectionByNameLRS.onInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/localConnectionByNameLRS.js:43
     19    0.0%    0.2%  LazyCompile: ~indexOf native string.js:115
     19    0.0%    0.2%  LazyCompile: STRING_ADD_LEFT native runtime.js:183
     19    0.0%    0.2%  LazyCompile: $Array.get_ native v8natives.js:558
     18    0.0%    0.2%  LazyCompile: Lev.actions /home/chris/CDRReportServer/tags/1.1.0/common/levenshtein/lib/levenshtein.js:52
     18    0.0%    0.2%  LazyCompile: *UseSparseVariant native array.js:111
     18    0.0%    0.2%  LazyCompile: *NativeModule.compile node.js:541
     17    0.0%    0.2%  LazyCompile: *parserOnHeadersComplete http.js:48
     16    0.0%    0.2%  Stub: CompareICStub {1}
     16    0.0%    0.2%  LazyCompile: ToObject native runtime.js:577
     16    0.0%    0.2%  LazyCompile: IsDataDescriptor native v8natives.js:367
     16    0.0%    0.2%  LazyCompile: *Socket.write net.js:431
     15    0.0%    0.2%  Stub: KeyedLoadElementStub
     15    0.0%    0.2%  LazyCompile: *reduce native array.js:1242
     15    0.0%    0.2%  LazyCompile: *allocPool buffer.js:281
     14    0.0%    0.1%  LazyCompile: toString native v8natives.js:238
     14    0.0%    0.1%  Builtin: A builtin from the snapshot {5}
     13    0.0%    0.1%  Stub: RegExpConstructResultStub
     13    0.0%    0.1%  LazyCompile: b native string.js:36
     13    0.0%    0.1%  LazyCompile: Logger.log /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/logger.js:72
     13    0.0%    0.1%  LazyCompile: *VirtualLRS.order /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualLRS.js:279
     12    0.0%    0.1%  LazyCompile: VirtualLRS.emitDeltas /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualLRS.js:234
     12    0.0%    0.1%  LazyCompile: *socket.ondata http.js:1467
     12    0.0%    0.1%  LazyCompile: *exports.toArray /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/util.js:18
     12    0.0%    0.1%  Function: ~<anonymous> util.js:359
     12    0.0%    0.1%  Function: ~<anonymous> /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/sock.js:21
     12    0.0%    0.1%  Builtin: A builtin from the snapshot {1}
     11    0.0%    0.1%  LazyCompile: *getOwnPropertyDescriptor native v8natives.js:870
     11    0.0%    0.1%  LazyCompile: *VirtualLRS.onInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualLRS.js:86
     11    0.0%    0.1%  LazyCompile: *Manager.checkRequest /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/manager.js:897
     10    0.0%    0.1%  LazyCompile: ~BasicSerializeArray native json.js:181
     10    0.0%    0.1%  LazyCompile: *isArray util.js:380
     10    0.0%    0.1%  LazyCompile: *exports.active timers.js:143
     10    0.0%    0.1%  LazyCompile: *$Array.enumerable_ native v8natives.js:528
     10    0.0%    0.1%  LazyCompile: $Array.writable_ native v8natives.js:538
     10    0.0%    0.1%  Function: ~formatValue util.js:153
      9    0.0%    0.1%  Stub: ToBooleanStub_UndefinedBoolNullSmiSpecObjectStringHeapNumber
      9    0.0%    0.1%  LazyCompile: ~Module._compile module.js:364
      9    0.0%    0.1%  LazyCompile: *reduceToSingleString util.js:357
      9    0.0%    0.1%  Function: ~EventEmitter.addListener events.js:99
      9    0.0%    0.1%  Function: ~<anonymous> util.js:324
      8    0.0%    0.1%  Stub: StringAddStub
      8    0.0%    0.1%  Stub: CallFunctionStub_Args3_Implicit
      8    0.0%    0.1%  LazyCompile: ~DoConstructRegExp native regexp.js:35
      8    0.0%    0.1%  LazyCompile: ToPrimitive native runtime.js:516
      8    0.0%    0.1%  LazyCompile: *objectToString util.js:405
      8    0.0%    0.1%  LazyCompile: *Transport.setHandlers /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/transport.js:89
      8    0.0%    0.1%  Function: ~NativeModule.compile node.js:541
      7    0.0%    0.1%  Stub: CallFunctionStub
      7    0.0%    0.1%  LazyCompile: *diff /home/chris/CDRReportServer/tags/1.1.0/common/levenshtein/lib/levenshtein.js:43
      7    0.0%    0.1%  LazyCompile: *StringReplaceGlobalRegExpWithFunction native string.js:396
      7    0.0%    0.1%  LazyCompile: $Array.enumerable_ native v8natives.js:535
      7    0.0%    0.1%  KeyedLoadIC: args_count: 0 {2}
      7    0.0%    0.1%  Function: ~Module._compile module.js:364
      6    0.0%    0.1%  Stub: CompareStub {1}
      6    0.0%    0.1%  LazyCompile: *handleInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/sourceClock.js:17
      6    0.0%    0.1%  LazyCompile: *forEach native array.js:1019
      6    0.0%    0.1%  LazyCompile: *LocalConnectionByNameLRS.aggregateInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/localConnectionByNameLRS.js:31
      6    0.0%    0.1%  LazyCompile: *$Array.configurable_ native v8natives.js:548
      6    0.0%    0.1%  LazyCompile: $Array.get_ native v8natives.js:565
      6    0.0%    0.1%  Function: ~ondrain stream.js:46
      6    0.0%    0.1%  Function: ~isRegExp util.js:387
      5    0.0%    0.1%  Stub: FastNewClosureStub
      5    0.0%    0.1%  Stub: CallFunctionStub {2}
      5    0.0%    0.1%  Stub: BinaryOpStub_ADD_OverwriteLeft_BothStrings
      5    0.0%    0.1%  LazyCompile: ~isArray native array.js:1311
      5    0.0%    0.1%  LazyCompile: ~handleInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/sourceClock.js:17
      5    0.0%    0.1%  LazyCompile: ~VirtualAggregatingLRS.getOrCreateBin /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualAggregatingLRS.js:31
      5    0.0%    0.1%  LazyCompile: res.render /home/chris/CDRReportServer/tags/1.1.0/node_modules/express/lib/view.js:308
      5    0.0%    0.1%  LazyCompile: WeekDays native date.js:398
      5    0.0%    0.1%  LazyCompile: APPLY_PREPARE native runtime.js:449
      5    0.0%    0.1%  LazyCompile: *PersistentConnection.createConnectionNow /home/chris/CDRReportServer/tags/1.1.0/common/persistent_connection.js:43
      5    0.0%    0.1%  KeyedLoadIC: args_count: 0 {7}
      5    0.0%    0.1%  Function: ~Object.getOwnPropertyDescriptor.value util.js:288
      5    0.0%    0.1%  Function: ~<anonymous> /home/chris/CDRReportServer/tags/1.1.0/node_modules/express/node_modules/connect/lib/middleware/session/memory.js:43
      5    0.0%    0.1%  Builtin: A builtin from the snapshot {7}
      4    0.0%    0.0%  Stub: ToBooleanStub {2}
      4    0.0%    0.0%  Stub: FastNewContextStub {1}
      4    0.0%    0.0%  Stub: CompareICStub {2}
      4    0.0%    0.0%  Stub: CallFunctionStub_Args6
      4    0.0%    0.0%  LazyCompile: ~test native regexp.js:223
      4    0.0%    0.0%  LazyCompile: ~stringify native json.js:307
      4    0.0%    0.0%  LazyCompile: ~$Array.configurable_ native v8natives.js:552
      4    0.0%    0.0%  LazyCompile: that.emitDebug._table /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/dbcee.js:20
      4    0.0%    0.0%  LazyCompile: exports.setTimeout timers.js:162
      4    0.0%    0.0%  LazyCompile: IN native runtime.js:354
      4    0.0%    0.0%  LazyCompile: *toLowerCase native string.js:742
      4    0.0%    0.0%  LazyCompile: *min native math.js:140
      4    0.0%    0.0%  LazyCompile: *exports.setInterval.timer.ontimeout timers.js:222
      4    0.0%    0.0%  LazyCompile: *encodeURIComponent native uri.js:314
      4    0.0%    0.0%  LazyCompile: *afterWrite net.js:494
      4    0.0%    0.0%  LazyCompile: *XHRPolling.doWrite /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/transports/xhr-polling.js:50
      4    0.0%    0.0%  LazyCompile: *Transport.clearHandlers /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/transport.js:127
      4    0.0%    0.0%  LazyCompile: *MdipSuccessesLimitNLRS.isValidToInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/mdipSuccessesLimitNLRS.js:37
      4    0.0%    0.0%  LazyCompile: *$Array.enumerable_ native v8natives.js:532
      4    0.0%    0.0%  LazyCompile: $Array.writable_ native v8natives.js:542
      4    0.0%    0.0%  KeyedStoreIC: A keyed store IC from the snapshot
      4    0.0%    0.0%  Function: ~startup.processNextTick.process._tickCallback node.js:184
      4    0.0%    0.0%  Function: ~render /home/chris/CDRReportServer/tags/1.1.0/frontend/frontend.js:564
      4    0.0%    0.0%  Function: ~objectToString util.js:405
      4    0.0%    0.0%  Function: ~<anonymous> util.js:238
      4    0.0%    0.0%  Function: ~<anonymous> path.js:169
      4    0.0%    0.0%  Function: ~<anonymous> /home/chris/CDRReportServer/tags/1.1.0/node_modules/express/node_modules/connect/lib/middleware/session/memory.js:73
      3    0.0%    0.0%  Stub: ToBooleanStub_UndefinedSpecObject
      3    0.0%    0.0%  Stub: StringAddStub {2}
      3    0.0%    0.0%  Stub: InstanceofStub
      3    0.0%    0.0%  Stub: CallFunctionStub_Args6_Implicit
      3    0.0%    0.0%  Stub: BinaryOpStub {1}
      3    0.0%    0.0%  LazyCompile: ~VirtualAggregatingLRS.onInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualAggregatingLRS.js:53
      3    0.0%    0.0%  LazyCompile: ~LocalConnectionByNameLRS.aggregateInsert /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/localConnectionByNameLRS.js:31
      3    0.0%    0.0%  LazyCompile: DefineOwnProperty native v8natives.js:692
      3    0.0%    0.0%  LazyCompile: *onread net.js:347
      3    0.0%    0.0%  LazyCompile: *VirtualLRS.init.process.dbcee.runSql.that.rset /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualLRS.js:30
      3    0.0%    0.0%  LazyCompile: *Transport.handleRequest.req /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/transport.js:40
      3    0.0%    0.0%  LazyCompile: *NativeModule.require node.js:496
      3    0.0%    0.0%  LazyCompile: *$Array.configurable_ native v8natives.js:552
      3    0.0%    0.0%  Function: ~isError util.js:399
      3    0.0%    0.0%  Function: ~formatProperty util.js:298
      3    0.0%    0.0%  Function: ~formatError util.js:273
      3    0.0%    0.0%  Function: ~NativeModule.getCached node.js:520
      3    0.0%    0.0%  Function: ~<anonymous> /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/sock.js:52
      3    0.0%    0.0%  Function: startup.processNextTick.process._tickCallback node.js:184
      3    0.0%    0.0%  Function: Module._compile module.js:364
      3    0.0%    0.0%  Builtin: A builtin from the snapshot {6}
      3    0.0%    0.0%  Builtin: A builtin from the snapshot {4}
      2    0.0%    0.0%  Stub: ToBooleanStub {1}
      2    0.0%    0.0%  Stub: KeyedStoreElementStub
      2    0.0%    0.0%  Stub: JSEntryStub
      2    0.0%    0.0%  Stub: FastNewContextStub
      2    0.0%    0.0%  Stub: FastCloneShallowArrayStub {2}
      2    0.0%    0.0%  Stub: CompareStub_LT
      2    0.0%    0.0%  Stub: CompareICStub {4}
      2    0.0%    0.0%  Stub: CompareICStub
      2    0.0%    0.0%  Stub: CallFunctionStub {1}
      2    0.0%    0.0%  Stub: BinaryOpStub_SUB_Alloc_SMI
      2    0.0%    0.0%  Stub: BinaryOpStub_SHR_Alloc_SMI
      2    0.0%    0.0%  Stub: BinaryOpStub {2}
      2    0.0%    0.0%  LazyCompile: ~ceil native math.js:80
      2    0.0%    0.0%  LazyCompile: ~InstantiateFunction native apinatives.js:65
      2    0.0%    0.0%  LazyCompile: levels.forEach.Logger.(anonymous function) /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/logger.js:94
      2    0.0%    0.0%  LazyCompile: isFinite native v8natives.js:115
      2    0.0%    0.0%  LazyCompile: captureStackTrace native messages.js:1054
      2    0.0%    0.0%  LazyCompile: INSTANCE_OF native runtime.js:367
      2    0.0%    0.0%  LazyCompile: DefineOneShotAccessor native messages.js:727
      2    0.0%    0.0%  LazyCompile: DELETE native runtime.js:348
      2    0.0%    0.0%  LazyCompile: *isDate util.js:393
      2    0.0%    0.0%  LazyCompile: *exec native regexp.js:167
      2    0.0%    0.0%  LazyCompile: *emitLocalConnection /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/dbcee.js:31
      2    0.0%    0.0%  LazyCompile: *append _linklist.js:63
      2    0.0%    0.0%  LazyCompile: *ToUint32 native runtime.js:596
      2    0.0%    0.0%  LazyCompile: *EventEmitter.addListener events.js:99
      2    0.0%    0.0%  LazyCompile: *DBCEE.emitDebug /home/chris/CDRReportServer/tags/1.1.0/frontend/lib/dbcee.js:80
      2    0.0%    0.0%  LazyCompile: *<anonymous> /home/chris/CDRReportServer/tags/1.1.0/node_modules/express/node_modules/connect/lib/patch.js:33
      2    0.0%    0.0%  KeyedLoadIC: args_count: 0 {6}
      2    0.0%    0.0%  KeyedLoadIC: A keyed load IC from the snapshot {1}
      2    0.0%    0.0%  Function: ~startup.globalTimeouts.global.setInterval node.js:139
      2    0.0%    0.0%  Function: ~inspect util.js:94
      2    0.0%    0.0%  Function: ~exports.normalize path.js:301
      2    0.0%    0.0%  Function: ~dashboard /home/chris/CDRReportServer/tags/1.1.0/frontend/frontend.js:501
      1    0.0%    0.0%  Stub: ToBooleanStub_UndefinedString
      1    0.0%    0.0%  Stub: ToBooleanStub_String
      1    0.0%    0.0%  Stub: ToBooleanStub_Smi
      1    0.0%    0.0%  Stub: StringAddStub {1}
      1    0.0%    0.0%  Stub: JSEntryStub {1}
      1    0.0%    0.0%  Stub: FastNewContextStub {3}
      1    0.0%    0.0%  Stub: FastNewContextStub {2}
      1    0.0%    0.0%  Stub: FastCloneShallowArrayStub {1}
      1    0.0%    0.0%  Stub: FastCloneShallowArrayStub
      1    0.0%    0.0%  Stub: CompareICStub {8}
      1    0.0%    0.0%  Stub: CompareICStub {7}
      1    0.0%    0.0%  Stub: CompareICStub {6}
      1    0.0%    0.0%  Stub: CompareICStub {5}
      1    0.0%    0.0%  Stub: CallFunctionStub {3}
      1    0.0%    0.0%  Stub: BinaryOpStub
      1    0.0%    0.0%  RegExp: ([^:]+):([0-9]+)?(\\+)?:([^:]+)?:?([\\s\\S]*)?
      1    0.0%    0.0%  LazyCompile: ~setTime native date.js:771
      1    0.0%    0.0%  LazyCompile: ~SubString native string.js:200
      1    0.0%    0.0%  LazyCompile: ~NativeModule.require node.js:496
      1    0.0%    0.0%  LazyCompile: ~MdipSuccessesInPeriodLRS.getResultSet /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/mdipSuccessesInPeriodLRS.js:45
      1    0.0%    0.0%  LazyCompile: ~GetOwnEnumerablePropertyNames native v8natives.js:1011
      1    0.0%    0.0%  LazyCompile: ~DoRegExpExec native regexp.js:119
      1    0.0%    0.0%  LazyCompile: ~ConfigureTemplateInstance native apinatives.js:105
      1    0.0%    0.0%  LazyCompile: ~BasicJSONSerialize native json.js:273
      1    0.0%    0.0%  LazyCompile: ~<anonymous> /home/chris/CDRReportServer/tags/1.1.0/node_modules/v8-profiler/v8-profiler.js:1
      1    0.0%    0.0%  LazyCompile: ~<anonymous>
      1    0.0%    0.0%  LazyCompile: ~$Array.enumerable_ native v8natives.js:532
      1    0.0%    0.0%  LazyCompile: ~$Array.enumerable_ native v8natives.js:528
      1    0.0%    0.0%  LazyCompile: d native v8natives.js:582
      1    0.0%    0.0%  LazyCompile: bind native v8natives.js:1456
      1    0.0%    0.0%  LazyCompile: b native v8natives.js:1264
      1    0.0%    0.0%  LazyCompile: VirtualAggregatingLRS.getOrCreateBin /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualAggregatingLRS.js:31
      1    0.0%    0.0%  LazyCompile: NewFunction native v8natives.js:1527
      1    0.0%    0.0%  LazyCompile: EQUALS native runtime.js:54
      1    0.0%    0.0%  LazyCompile: COMPARE native runtime.js:120
      1    0.0%    0.0%  LazyCompile: ADD native runtime.js:163
      1    0.0%    0.0%  LazyCompile: *stylizeNoColor util.js:148
      1    0.0%    0.0%  LazyCompile: *sto /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualRollingLRS.js:38
      1    0.0%    0.0%  LazyCompile: *startup.globalTimeouts.global.clearTimeout node.js:144
      1    0.0%    0.0%  LazyCompile: *formatValue util.js:153
      1    0.0%    0.0%  LazyCompile: *exports.warn console.js:32
      1    0.0%    0.0%  LazyCompile: *cmd.process_packet /home/chris/CDRReportServer/tags/1.1.0/node_modules/mysql-native/lib/mysql-native/command.js:27
      1    0.0%    0.0%  LazyCompile: *TxnByTxnStartLRS.augmentRow /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/txnByTxnStartLRS.js:61
      1    0.0%    0.0%  LazyCompile: *Transport.handleRequest.req /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/transport.js:50
      1    0.0%    0.0%  LazyCompile: *Socket.dispatch /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/socket.js:228
      1    0.0%    0.0%  LazyCompile: *OutgoingMessage.write http.js:588
      1    0.0%    0.0%  LazyCompile: *OutgoingMessage.setHeader http.js:524
      1    0.0%    0.0%  LazyCompile: *MdipSuccessesByTxnStartLRS.augmentRow /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/mdipSuccessesByTxnStartLRS.js:64
      1    0.0%    0.0%  LazyCompile: *Manager.get /home/chris/CDRReportServer/tags/1.1.0/node_modules/socket.io/lib/manager.js:156
      1    0.0%    0.0%  LazyCompile: *LocalTimezoneString native date.js:498
      1    0.0%    0.0%  LazyCompile: *CryptoStream.resume tls.js:161
      1    0.0%    0.0%  LazyCompile: *ConnectionByNameLRS.augmentRow /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/connectionByNameLRS.js:45
      1    0.0%    0.0%  LazyCompile: $Array.set_ native v8natives.js:568
      1    0.0%    0.0%  KeyedStoreIC: args_count: 0 {9}
      1    0.0%    0.0%  KeyedLoadIC: store
      1    0.0%    0.0%  KeyedLoadIC: args_count: 0 {8}
      1    0.0%    0.0%  KeyedLoadIC: args_count: 0 {5}
      1    0.0%    0.0%  KeyedLoadIC: args_count: 0 {4}
      1    0.0%    0.0%  KeyedLoadIC: args_count: 0 {3}
      1    0.0%    0.0%  KeyedLoadIC: args_count: 0 {1}
      1    0.0%    0.0%  KeyedLoadIC: args_count: 0 {10}
      1    0.0%    0.0%  Function: ~str util.js:328
      1    0.0%    0.0%  Function: ~sto /home/chris/CDRReportServer/tags/1.1.0/frontend/lrs/virtualRollingLRS.js:38
      1    0.0%    0.0%  Function: ~splitPath path.js:265
      1    0.0%    0.0%  Function: ~require.registerExtension module.js:387
      1    0.0%    0.0%  Function: ~readPackage module.js:97
      1    0.0%    0.0%  Function: ~isBuffer buffer.js:288
      1    0.0%    0.0%  Function: ~fs.lstatSync fs.js:419
      1    0.0%    0.0%  Function: ~exports.stopProfiling /home/chris/CDRReportServer/tags/1.1.0/node_modules/v8-profiler/v8-profiler.js:220
      1    0.0%    0.0%  Function: ~exports.resolve path.js:272
      1    0.0%    0.0%  Function: ~coerce buffer.js:199
      1    0.0%    0.0%  Function: ~Stream stream.js:25
      1    0.0%    0.0%  Function: ~SlowBuffer.slice buffer.js:185
      1    0.0%    0.0%  Function: ~NativeModule.require node.js:496
      1    0.0%    0.0%  Function: ~<anonymous> node.js:280
      1    0.0%    0.0%  Function: ~<anonymous> fs.js:152

 [C++]:
   ticks  total  nonlib   name

 [GC]:
   ticks  total  nonlib   name
    776    0.6%

 [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 2.0% are not shown.

   ticks parent  name
  111345   91.6%  /lib/libc-2.12.1.so

Re: Profiling problem, is 91% of ticks in libc 'normal'. mscdex 10/4/12 9:56 AM
On Oct 4, 12:23 pm, Chris Dew <cms...@gmail.com> wrote:
> I'm starting to have a speed problem with a production NodeJS application
> (20-100% cpu usage).

Have you tried profiling with idle notifications disabled for
comparison purposes?
Re: [nodejs] Profiling problem, is 91% of ticks in libc 'normal'. Ben Noordhuis 10/4/12 7:22 PM
On Thu, Oct 4, 2012 at 6:22 PM, Chris Dew <cms...@gmail.com> wrote:
> I'm starting to have a speed problem with a production NodeJS application
> (20-100% cpu usage).
>
> I've run it with --prof and used node-tick-processor.
>
> Is 91% of ticks in libc 'normal'?

It can be, if your application spends a lot of time waiting for new
events in epoll_wait().

A quick way to check that is `strace -c node app.js` and `time node
app.js`. One prints a tally of system calls, the other a breakdown of
system vs. user time.

> P.S. is there a way to show the 'unaccounted' ticks?  I expect it needs to
> be told where to find the source of the app.

Not that I know of.

I don't think it's due to missing sources. Unaccounted ticks are ticks
where V8's profiler thread was not able to make sense of either the
instruction pointer or the stack pointer.
Re: Profiling problem, is 91% of ticks in libc 'normal'. Perf Tech 3/13/14 8:02 AM
I got 80% is in my test on a node based web app. The test was by directing a client emulator (like "ab") at the app/server.
Majority of the test were spending on 
  • Access a few fixed files or directories (open the file/directory, fstats, read and close)
    • open file
    • open directory
    • fstats
    • read
    • close
  • socket side;
    • accept 
    • getsockname
    • epoll
    • read
    • write
...
Re: Profiling problem, is 91% of ticks in libc 'normal'. Michael Hart 3/13/14 8:29 PM
Make sure you're using the deps from your actual node version too - I've run into problems with this before, so I just use this gist now: https://gist.github.com/mhart/5107424

for file in splaytree codemap csvparser consarray profile profile_view logreader tickprocessor tickprocessor-driver; \
do curl https://raw.github.com/joyent/node/$(node --version)/deps/v8/tools/$file.js; \
done) > nprof && chmod 755 nprof

(and then run `nprof` whereever you have your v8.log)
...