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

1,091 views
Skip to first unread message

Chris Dew

unread,
Oct 4, 2012, 12:22:40 PM10/4/12
to nod...@googlegroups.com
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

mscdex

unread,
Oct 4, 2012, 12:56:15 PM10/4/12
to nodejs
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?

Ben Noordhuis

unread,
Oct 4, 2012, 10:22:19 PM10/4/12
to nod...@googlegroups.com
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.

Perf Tech

unread,
Mar 13, 2014, 11:02:18 AM3/13/14
to nod...@googlegroups.com
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

Michael Hart

unread,
Mar 13, 2014, 11:29:49 PM3/13/14
to nod...@googlegroups.com
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)
Reply all
Reply to author
Forward
0 new messages