node --trace-opt --trace-bailout bench/parse.js
[marking Parser.parse 0x1aaeac0a128 for recompilation, reason: hot and stable, ICs with typeinfo: 59/95 (62%)]
Bailout in HGraphBuilder: @"Parser.parse": SwitchStatement: non-literal switch label
[disabled optimization for Parser.parse]
[marking EventEmitter.emit 0x1f0e63861860 for recompilation, reason: not much type info but very hot, ICs with typeinfo: 2/70 (2%)]
[optimizing: EventEmitter.emit / 1f0e63861861 - took 1.649 ms]
[marking EventEmitter 0x1aaeac2bbb0 for recompilation, reason: small function, ICs with typeinfo: 1/5 (20%)]
[marking createParser 0x1aaeac38f88 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[optimizing: createParser / 1aaeac38f89 - took 0.124 ms]
[optimizing: EventEmitter / 1aaeac2bbb1 - took 0.189 ms]
[marking getOwnPropertyNames 0x1f0e6384fbd8 for recompilation, reason: hot and stable, ICs with typeinfo: 5/19 (26%)]
[optimizing: getOwnPropertyNames / 1f0e6384fbd9 - took 0.516 ms]
[marking Parser 0x1aaeac29ba0 for recompilation, reason: hot and stable, ICs with typeinfo: 18/18 (100%)]
[marking Parser.end 0x1aaeac0a0e0 for recompilation, reason: hot and stable, ICs with typeinfo: 6/32 (18%)]
[optimizing: Parser / 1aaeac29ba1 - took 0.558 ms]
[optimizing: Parser.end / 1aaeac0a0e1 - took 0.290 ms]
1189 ms
9327.165685449958 bytes/msAfter removing the switch statement and replacing it with if/else if/else statements:
node --trace-opt --trace-bailout bench/parse.js
[marking Parser.parse 0x32cbe550a128 for recompilation, reason: hot and stable, ICs with typeinfo: 59/95 (62%)]
[optimizing: Parser.parse / 32cbe550a129 - took 1.891 ms]
[marking EventEmitter.emit 0x247e6d761860 for recompilation, reason: not much type info but very hot, ICs with typeinfo: 2/70 (2%)]
[optimizing: EventEmitter.emit / 247e6d761861 - took 0.945 ms]
[marking EventEmitter 0x32cbe552cbf8 for recompilation, reason: small function, ICs with typeinfo: 1/5 (20%)]
[marking createParser 0x32cbe5539ff8 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[optimizing: createParser / 32cbe5539ff9 - took 0.135 ms]
[optimizing: EventEmitter / 32cbe552cbf9 - took 0.188 ms]
[marking getOwnPropertyNames 0x247e6d74fbd8 for recompilation, reason: hot and stable, ICs with typeinfo: 5/19 (26%)]
[optimizing: getOwnPropertyNames / 247e6d74fbd9 - took 0.485 ms]
[marking Parser 0x32cbe552abe8 for recompilation, reason: hot and stable, ICs with typeinfo: 18/18 (100%)]
[marking Parser.end 0x32cbe550a0e0 for recompilation, reason: hot and stable, ICs with typeinfo: 6/32 (18%)]
[optimizing: Parser / 32cbe552abe9 - took 0.527 ms]
[optimizing: Parser.end / 32cbe550a0e1 - took 0.289 ms]
767 ms
14458.930899608866 bytes/mNow my code is optimized by v8, I would like to know what is slow in my code, having hard time trying to understand the logs ...
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/csv-stream$ node --prof bench/parse.js
798 ms
13897.243107769424 bytes/ms
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/csv-stream$ node-tick-processor
Statistical profiling result from node, (804 ticks, 389 unaccounted, 0 excluded).
[Unknown]:
ticks total nonlib name
389 48.4%
[Shared libraries]:
ticks total nonlib name
25 3.1% 0.0% /lib/x86_64-linux-gnu/libc-2.13.so
1 0.1% 0.0% /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.16
1 0.1% 0.0% /lib/x86_64-linux-gnu/libpthread-2.13.so
[JavaScript]:
ticks total nonlib name
530 65.9% 68.2% LazyCompile: *Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
164 20.4% 21.1% Stub: StringAddStub
21 2.6% 2.7% LazyCompile: *EventEmitter.emit events.js:49
18 2.2% 2.3% Function: ~NativeModule.compile node.js:613
5 0.6% 0.6% Stub: CEntryStub
4 0.5% 0.5% Builtin: A builtin from the snapshot
3 0.4% 0.4% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
3 0.4% 0.4% LazyCompile: *getOwnPropertyNames native v8natives.js:977
3 0.4% 0.4% KeyedStoreIC: A keyed store IC from the snapshot
2 0.2% 0.3% LazyCompile: *Parser /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:17
2 0.2% 0.3% Function: ~Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
1 0.1% 0.1% Stub: KeyedStoreElementStub
1 0.1% 0.1% LazyCompile: ~defineProperties native v8natives.js:1102
1 0.1% 0.1% LazyCompile: ~ToPropertyDescriptor native v8natives.js:420
1 0.1% 0.1% LazyCompile: ~SubString native string.js:205
1 0.1% 0.1% LazyCompile: ~<anonymous> module.js:1
1 0.1% 0.1% LazyCompile: ~<anonymous> fs.js:1
1 0.1% 0.1% LazyCompile: SUB native runtime.js:214
1 0.1% 0.1% LazyCompile: RegExpConstructor native regexp.js:86
1 0.1% 0.1% LazyCompile: IN native runtime.js:354
1 0.1% 0.1% LazyCompile: *EventEmitter events.js:25
1 0.1% 0.1% Function: ~startup.lazyConstants node.js:197
1 0.1% 0.1% Function: ~Module._nodeModulePaths module.js:207
1 0.1% 0.1% Function: ~Module._compile module.js:372
1 0.1% 0.1% Function: ~EventEmitter events.js:25
1 0.1% 0.1% Function: ~Buffer.toString buffer.js:392
1 0.1% 0.1% Builtin: A builtin from the snapshot {1}
[C++]:
ticks total nonlib name
[GC]:
ticks total nonlib name
4 0.5%
[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
530 65.9% LazyCompile: *Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
362 68.3% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
362 100.0% Function: ~Module._compile module.js:372
362 100.0% Function: ~Module._extensions..js module.js:465
362 100.0% Function: ~Module.load module.js:346
362 100.0% Function: Module._load module.js:275
168 31.7% LazyCompile: *EventEmitter events.js:25
168 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
168 100.0% Function: ~Module._compile module.js:372
168 100.0% Function: ~Module._extensions..js module.js:465
168 100.0% Function: ~Module.load module.js:346
164 20.4% Stub: StringAddStub
164 100.0% LazyCompile: *Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
164 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
164 100.0% Function: ~Module._compile module.js:372
164 100.0% Function: ~Module._extensions..js module.js:465
164 100.0% Function: ~Module.load module.js:346
25 3.1% /lib/x86_64-linux-gnu/libc-2.13.so
9 36.0% Function: ~NativeModule.compile node.js:613
9 100.0% Function: ~NativeModule.require node.js:568
7 77.8% Function: ~tryFile module.js:138
7 100.0% Function: ~Module._findPath module.js:160
7 100.0% Function: ~Module._resolveFilename module.js:323
1 11.1% LazyCompile: ~<anonymous> fs.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 11.1% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
2 8.0% Function: ~NativeModule.require node.js:568
1 50.0% LazyCompile: ~<anonymous> assert.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 100.0% LazyCompile: ~<anonymous> buffer.js:1
1 50.0% Function: ~startup.globalVariables node.js:158
1 100.0% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
1 4.0% LazyCompile: ~replace native string.js:221
1 100.0% Function: ~Module._compile module.js:372
1 100.0% Function: ~Module._extensions..js module.js:465
1 100.0% Function: ~Module.load module.js:346
1 100.0% Function: Module._load module.js:275
1 4.0% LazyCompile: ~DefineObjectProperty native v8natives.js:695
1 100.0% LazyCompile: ~DefineOwnProperty native v8natives.js:924
1 100.0% LazyCompile: ~defineProperties native v8natives.js:1102
1 100.0% LazyCompile: ~create native v8natives.js:1038
1 100.0% Function: ~exports.inherits util.js:536
1 4.0% LazyCompile: *createParser /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:32
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
1 100.0% Function: ~Module._compile module.js:372
1 100.0% Function: ~Module._extensions..js module.js:465
1 100.0% Function: ~Module.load module.js:346
1 4.0% LazyCompile: *Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
1 100.0% Function: ~Module._compile module.js:372
1 100.0% Function: ~Module._extensions..js module.js:465
1 100.0% Function: ~Module.load module.js:346
1 4.0% Function: ~start fs.js:1007
1 100.0% Function: ~realpathSync fs.js:984
1 100.0% Function: ~tryFile module.js:138
1 100.0% Function: ~Module._findPath module.js:160
1 100.0% Function: ~Module._resolveFilename module.js:323
1 4.0% Function: ~realpathSync fs.js:984
1 100.0% Function: ~tryFile module.js:138
1 100.0% Function: ~Module._findPath module.js:160
1 100.0% Function: ~Module._resolveFilename module.js:323
1 100.0% Function: Module._load module.js:275
1 4.0% Function: ~Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
1 100.0% Function: ~Module._compile module.js:372
1 100.0% Function: ~Module._extensions..js module.js:465
1 100.0% Function: ~Module.load module.js:346
1 4.0% Function: ~Parser /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:17
1 100.0% Function: ~createParser /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:32
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
1 100.0% Function: ~Module._compile module.js:372
1 100.0% Function: ~Module._extensions..js module.js:465
1 4.0% Function: ~Module.load module.js:346
1 100.0% Function: Module._load module.js:275
1 100.0% Function: ~Module.require module.js:361
1 100.0% Function: ~require module.js:377
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
1 4.0% Function: ~Module._resolveLookupPaths module.js:231
1 100.0% Function: ~Module._resolveFilename module.js:323
1 100.0% Function: Module._load module.js:275
1 100.0% Function: ~Module.require module.js:361
1 100.0% Function: ~require module.js:377
1 4.0% Function: ~Module._findPath module.js:160
1 100.0% Function: ~Module._resolveFilename module.js:323
1 100.0% Function: Module._load module.js:275
1 100.0% Function: ~Module.require module.js:361
1 100.0% Function: ~require module.js:377
1 4.0% Function: ~Buffer buffer.js:204
1 100.0% Function: fs.readFileSync fs.js:181
1 100.0% Function: ~Module._extensions..js module.js:465
1 100.0% Function: ~Module.load module.js:346
1 100.0% Function: Module._load module.js:275
1 4.0% Function: Module._load module.js:275
1 100.0% Function: ~Module.runMain module.js:490
1 100.0% Function: ~startup.processNextTick.process._tickCallback node.js:233
21 2.6% LazyCompile: *EventEmitter.emit events.js:49
11 52.4% LazyCompile: *EventEmitter.emit events.js:49
11 100.0% LazyCompile: *Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
11 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
11 100.0% Function: ~Module._compile module.js:372
11 100.0% Function: ~Module._extensions..js module.js:465
10 47.6% LazyCompile: *Parser.parse /home/lbdremy/workspace/nodejs/csv-stream/lib/parser.js:48
10 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1
10 100.0% Function: ~Module._compile module.js:372
10 100.0% Function: ~Module._extensions..js module.js:465
10 100.0% Function: ~Module.load module.js:346
18 2.2% Function: ~NativeModule.compile node.js:613
18 100.0% Function: ~NativeModule.require node.js:568
6 33.3% Function: ~startup node.js:30
6 100.0% LazyCompile: ~<anonymous> node.js:27
4 22.2% LazyCompile: ~<anonymous> tty.js:1
4 100.0% Function: ~NativeModule.compile node.js:613
4 100.0% Function: ~NativeModule.require node.js:568
4 100.0% Function: ~createWritableStdioStream node.js:296
4 22.2% Function: ~tryFile module.js:138
4 100.0% Function: ~Module._findPath module.js:160
4 100.0% Function: ~Module._resolveFilename module.js:323
4 100.0% Function: Module._load module.js:275
1 5.6% LazyCompile: ~<anonymous> net.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 100.0% LazyCompile: ~<anonymous> tty.js:1
1 5.6% LazyCompile: ~<anonymous> assert.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 100.0% LazyCompile: ~<anonymous> buffer.js:1
1 5.6% Function: ~startup.globalVariables node.js:158
1 100.0% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
1 5.6% Function: ~createWritableStdioStream node.js:296
1 100.0% Function: ~<anonymous> node.js:355
1 100.0% Function: ~exports.log console.js:24
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/csv-stream/bench/parse.js:1