1° profiling:
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node --trace-opt --trace-bailout bench.js
[marking toLowerCase 0x2101a5499e8 for recompilation, reason: small function, ICs with typeinfo: 0/2 (0%)]
[optimizing: toLowerCase / 2101a5499e9 - took 0.804 ms]
[marking parse 0x2101a54a4e0 for recompilation, reason: small function, ICs with typeinfo: 2/4 (50%)]
[optimizing: parse / 2101a54a4e1 - took 0.134 ms]
[marking IsPrimitive 0x2101a553578 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[marking NonStringToString 0x2101a552338 for recompilation, reason: small function, ICs with typeinfo: 2/2 (100%)]
Bailout in HGraphBuilder: @"NonStringToString": call to a JavaScript runtime function
[disabled optimization for NonStringToString]
[optimizing: IsPrimitive / 2101a553579 - took 0.044 ms]
[marking Buffer.toString 0x2101a570570 for recompilation, reason: hot and stable, ICs with typeinfo: 9/37 (24%)]
[optimizing: Buffer.toString / 2101a570571 - took 0.595 ms]
[marking DefaultString 0x2101a5532e8 for recompilation, reason: hot and stable, ICs with typeinfo: 2/7 (28%)]
Bailout in HGraphBuilder: @"DefaultString": call to a JavaScript runtime function
[disabled optimization for DefaultString]
[marking proto.write 0x37b3ed20ac50 for recompilation, reason: hot and stable, ICs with typeinfo: 105/357 (29%)]
Bailout in HGraphBuilder: @"proto.write": SwitchStatement: non-literal switch label
[disabled optimization for proto.write]
[marking proto.onValue 0x37b3ed20ae68 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[marking proto.emit 0x37b3ed20ae20 for recompilation, reason: small function, ICs with typeinfo: 3/3 (100%)]
[optimizing: proto.emit / 37b3ed20ae21 - took 0.142 ms]
[marking proto.onToken 0x37b3ed20aeb0 for recompilation, reason: hot and stable, ICs with typeinfo: 41/77 (53%)]
Bailout in HGraphBuilder: @"proto.onToken": SwitchStatement: non-literal switch label
[disabled optimization for proto.onToken]
[marking proto.push 0x37b3ed20ad70 for recompilation, reason: small function, ICs with typeinfo: 8/8 (100%)]
[optimizing: proto.push / 37b3ed20ad71 - took 0.095 ms]
[marking proto.pop 0x37b3ed20add8 for recompilation, reason: small function, ICs with typeinfo: 11/12 (91%)]
[optimizing: proto.pop / 37b3ed20add9 - took 0.189 ms]
[optimizing: proto.onValue / 37b3ed20ae69 - took 0.024 ms]
[marking proto.pop 0x37b3ed20add8 for recompilation, reason: small function, ICs with typeinfo: 12/12 (100%)]
[optimizing: proto.pop / 37b3ed20add9 - took 0.176 ms]
[marking pow 0x2101a54aea0 for recompilation, reason: small function, ICs with typeinfo: 0/2 (0%)]
[optimizing: pow / 2101a54aea1 - took 0.162 ms]
JSON.parse took 103
streaming parser took 424
streaming is 4.116504854368932 times slowerlbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node --prof bench.js
JSON.parse took 104
streaming parser took 433
streaming is 4.163461538461538 times slower
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node-tick-processor
Statistical profiling result from node, (553 ticks, 231 unaccounted, 0 excluded).
[Unknown]:
ticks total nonlib name
231 41.8%
[Shared libraries]:
ticks total nonlib name
21 3.8% 0.0% /lib/x86_64-linux-gnu/libpthread-2.13.so
11 2.0% 0.0% /lib/x86_64-linux-gnu/libc-2.13.so
[JavaScript]:
ticks total nonlib name
186 33.6% 35.7% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
119 21.5% 22.8% Function: proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:334
77 13.9% 14.8% LazyCompile: *parse native json.js:55
18 3.3% 3.5% Function: ~NativeModule.compile node.js:613
17 3.1% 3.3% Stub: StringAddStub
12 2.2% 2.3% Stub: CompareICStub
11 2.0% 2.1% LazyCompile: ~parse native json.js:55
8 1.4% 1.5% LazyCompile: *proto.push /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:315
7 1.3% 1.3% Stub: KeyedLoadElementStub
7 1.3% 1.3% LazyCompile: *proto.pop /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:318
7 1.3% 1.3% KeyedLoadIC: args_count: 0
5 0.9% 1.0% Function: ~Buffer.toString buffer.js:392
4 0.7% 0.8% Stub: ToBooleanStub
3 0.5% 0.6% LazyCompile: *proto.emit /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:327
3 0.5% 0.6% LazyCompile: *Buffer.toString buffer.js:392
2 0.4% 0.4% Stub: CEntryStub
2 0.4% 0.4% Stub: BinaryOpStub
2 0.4% 0.4% KeyedStoreIC: A keyed store IC from the snapshot
2 0.4% 0.4% Function: ~Module._compile module.js:372
1 0.2% 0.2% Stub: ToBooleanStub_UndefinedSpecObject
1 0.2% 0.2% Stub: ToBooleanStub {1}
1 0.2% 0.2% Stub: RecordWriteStub {2}
1 0.2% 0.2% Stub: RecordWriteStub {1}
1 0.2% 0.2% Stub: RecordWriteStub
1 0.2% 0.2% Stub: MathPowStub
1 0.2% 0.2% Stub: InterruptStub
1 0.2% 0.2% Stub: FastCloneShallowArrayStub
1 0.2% 0.2% Stub: BinaryOpStub_MUL_OverwriteRight_HeapNumbers
1 0.2% 0.2% Stub: BinaryOpStub {1}
1 0.2% 0.2% RegExp: ^(\\/?)([\\s\\S]+\\/(?!$)|\\/)?((?:\\.{1\,2}$|[\\s\\S]+?)?(\\.[^.\\/]*)?)$
1 0.2% 0.2% LazyCompile: ~exec native regexp.js:171
1 0.2% 0.2% LazyCompile: ~<anonymous> node.js:27
1 0.2% 0.2% LazyCompile: ~<anonymous> fs.js:1
1 0.2% 0.2% LazyCompile: ~$Array.writable_ native v8natives.js:526
1 0.2% 0.2% Function: ~startup.processConfig node.js:214
1 0.2% 0.2% Function: ~proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
1 0.2% 0.2% Function: ~Parser /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:60
1 0.2% 0.2% Function: ~NativeModule.cache node.js:623
1 0.2% 0.2% Function: ~Module._resolveLookupPaths module.js:231
1 0.2% 0.2% Function: ~Module._nodeModulePaths module.js:207
1 0.2% 0.2% Function: ~EventEmitter.addListener events.js:127
[C++]:
ticks total nonlib name
[GC]:
ticks total nonlib name
5 0.9%
[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
186 33.6% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
185 99.5% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
185 100.0% Function: ~Module._compile module.js:372
185 100.0% Function: ~Module._extensions..js module.js:465
185 100.0% Function: ~Module.load module.js:346
185 100.0% Function: Module._load module.js:275
119 21.5% Function: proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:334
118 99.2% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
118 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
118 100.0% Function: ~Module._compile module.js:372
118 100.0% Function: ~Module._extensions..js module.js:465
118 100.0% Function: ~Module.load module.js:346
77 13.9% LazyCompile: *parse native json.js:55
77 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
77 100.0% Function: ~Module._compile module.js:372
77 100.0% Function: ~Module._extensions..js module.js:465
77 100.0% Function: ~Module.load module.js:346
77 100.0% Function: Module._load module.js:275
21 3.8% /lib/x86_64-linux-gnu/libpthread-2.13.so
13 61.9% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
13 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
13 100.0% Function: ~Module._compile module.js:372
13 100.0% Function: ~Module._extensions..js module.js:465
13 100.0% Function: ~Module.load module.js:346
3 14.3% LazyCompile: *proto.pop /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:318
3 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
3 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
3 100.0% Function: ~Module._compile module.js:372
3 100.0% Function: ~Module._extensions..js module.js:465
2 9.5% Function: proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:334
2 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
2 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
2 100.0% Function: ~Module._compile module.js:372
2 100.0% Function: ~Module._extensions..js module.js:465
1 4.8% LazyCompile: ~ToPropertyDescriptor native v8natives.js:420
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 100.0% LazyCompile: ~<anonymous> stream.js:1
1 4.8% LazyCompile: *proto.push /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:315
1 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
1 100.0% Function: ~Module._compile module.js:372
1 100.0% Function: ~Module._extensions..js module.js:465
18 3.3% Function: ~NativeModule.compile node.js:613
18 100.0% Function: ~NativeModule.require node.js:568
6 33.3% Function: ~tryFile module.js:138
6 100.0% Function: ~Module._findPath module.js:160
6 100.0% Function: ~Module._resolveFilename module.js:323
6 100.0% Function: Module._load module.js:275
4 22.2% Function: ~startup.globalVariables node.js:158
4 100.0% Function: ~startup node.js:30
4 100.0% LazyCompile: ~<anonymous> node.js:27
4 22.2% Function: ~startup node.js:30
4 100.0% LazyCompile: ~<anonymous> node.js:27
2 11.1% LazyCompile: ~<anonymous> tty.js:1
2 100.0% Function: ~NativeModule.compile node.js:613
2 100.0% Function: ~NativeModule.require node.js:568
2 100.0% Function: ~createWritableStdioStream node.js:296
1 5.6% LazyCompile: ~<anonymous> buffer.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 100.0% Function: ~startup.globalVariables node.js:158
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/jsonparse/bench.js:1
17 3.1% Stub: StringAddStub
17 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
17 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
17 100.0% Function: ~Module._compile module.js:372
17 100.0% Function: ~Module._extensions..js module.js:465
17 100.0% Function: ~Module.load module.js:346
12 2.2% Stub: CompareICStub
12 100.0% Function: proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:334
12 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
12 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
12 100.0% Function: ~Module._compile module.js:372
12 100.0% Function: ~Module._extensions..js module.js:465The hot functions are proto.write and proto.onToken. The first attempt to improve performance will be to replace switch/case statements by if/else if/else statements.
Let's start by proto.onToken.
Results:
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node --trace-opt --trace-bailout bench.js
[marking toLowerCase 0x1e9c98499e8 for recompilation, reason: small function, ICs with typeinfo: 0/2 (0%)]
[optimizing: toLowerCase / 1e9c98499e9 - took 0.852 ms]
[marking parse 0x1e9c984a4e0 for recompilation, reason: small function, ICs with typeinfo: 2/4 (50%)]
[optimizing: parse / 1e9c984a4e1 - took 0.135 ms]
[marking IsPrimitive 0x1e9c9853578 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[marking NonStringToString 0x1e9c9852338 for recompilation, reason: small function, ICs with typeinfo: 2/2 (100%)]
Bailout in HGraphBuilder: @"NonStringToString": call to a JavaScript runtime function
[disabled optimization for NonStringToString]
[optimizing: IsPrimitive / 1e9c9853579 - took 0.043 ms]
[marking Buffer.toString 0x1e9c9870570 for recompilation, reason: hot and stable, ICs with typeinfo: 9/37 (24%)]
[optimizing: Buffer.toString / 1e9c9870571 - took 0.550 ms]
[marking DefaultString 0x1e9c98532e8 for recompilation, reason: hot and stable, ICs with typeinfo: 2/7 (28%)]
Bailout in HGraphBuilder: @"DefaultString": call to a JavaScript runtime function
[disabled optimization for DefaultString]
[marking proto.write 0x1943e520ac50 for recompilation, reason: hot and stable, ICs with typeinfo: 105/357 (29%)]
Bailout in HGraphBuilder: @"proto.write": SwitchStatement: non-literal switch label
[disabled optimization for proto.write]
[marking proto.onValue 0x1943e520ae68 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[marking proto.emit 0x1943e520ae20 for recompilation, reason: small function, ICs with typeinfo: 3/3 (100%)]
[optimizing: proto.emit / 1943e520ae21 - took 0.135 ms]
[marking proto.onToken 0x1943e520aeb0 for recompilation, reason: hot and stable, ICs with typeinfo: 44/80 (55%)]
[optimizing: proto.onToken / 1943e520aeb1 - took 1.645 ms]
[optimizing: proto.onValue / 1943e520ae69 - took 0.025 ms]
[marking proto.onToken 0x1943e520aeb0 for recompilation, reason: hot and stable, ICs with typeinfo: 45/80 (56%)]
[optimizing: proto.onToken / 1943e520aeb1 - took 1.325 ms]
[marking proto.pop 0x1943e520add8 for recompilation, reason: small function, ICs with typeinfo: 12/12 (100%)]
[optimizing: proto.pop / 1943e520add9 - took 0.138 ms]
[marking pow 0x1e9c984aea0 for recompilation, reason: small function, ICs with typeinfo: 0/2 (0%)]
[optimizing: pow / 1e9c984aea1 - took 0.152 ms]
JSON.parse took 103
streaming parser took 370
streaming is 3.592233009708738 times slowerlbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node --prof bench.js
JSON.parse took 106
streaming parser took 381
streaming is 3.5943396226415096 times slower
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node-tick-processor
Statistical profiling result from node, (507 ticks, 233 unaccounted, 0 excluded).
[Unknown]:
ticks total nonlib name
233 46.0%
[Shared libraries]:
ticks total nonlib name
21 4.1% 0.0% /lib/x86_64-linux-gnu/libpthread-2.13.so
11 2.2% 0.0% /lib/x86_64-linux-gnu/libc-2.13.so
[JavaScript]:
ticks total nonlib name
187 36.9% 39.4% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
103 20.3% 21.7% LazyCompile: *proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:334
75 14.8% 15.8% LazyCompile: *parse native json.js:55
18 3.6% 3.8% Function: ~NativeModule.compile node.js:613
16 3.2% 3.4% Stub: StringAddStub
13 2.6% 2.7% LazyCompile: ~parse native json.js:55
8 1.6% 1.7% Stub: KeyedLoadElementStub
5 1.0% 1.1% KeyedLoadIC: args_count: 0
5 1.0% 1.1% Function: ~Buffer.toString buffer.js:392
4 0.8% 0.8% Stub: BinaryOpStub
4 0.8% 0.8% LazyCompile: *proto.pop /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:318
3 0.6% 0.6% KeyedStoreIC: A keyed store IC from the snapshot
2 0.4% 0.4% LazyCompile: ~DefaultString native runtime.js:645
2 0.4% 0.4% LazyCompile: *Buffer.toString buffer.js:392
2 0.4% 0.4% Function: ~Module._compile module.js:372
1 0.2% 0.2% Stub: ToBooleanStub_UndefinedBool
1 0.2% 0.2% Stub: ToBooleanStub
1 0.2% 0.2% Stub: RecordWriteStub {1}
1 0.2% 0.2% Stub: RecordWriteStub
1 0.2% 0.2% Stub: InterruptStub
1 0.2% 0.2% Stub: BinaryOpStub_MUL_OverwriteRight_HeapNumbers
1 0.2% 0.2% Stub: BinaryOpStub_ADD_OverwriteRight_HeapNumbers
1 0.2% 0.2% LazyCompile: ~split native string.js:554
1 0.2% 0.2% LazyCompile: ~defineProperties native v8natives.js:1102
1 0.2% 0.2% LazyCompile: ~create native v8natives.js:1038
1 0.2% 0.2% LazyCompile: ~BasicJSONSerialize native json.js:273
1 0.2% 0.2% LazyCompile: ~<anonymous> net.js:1
1 0.2% 0.2% LazyCompile: ~<anonymous> buffer.js:1
1 0.2% 0.2% LazyCompile: IN native runtime.js:354
1 0.2% 0.2% Function: ~startup.processConfig node.js:214
1 0.2% 0.2% Function: ~proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
1 0.2% 0.2% Function: ~fs.Stats.isDirectory fs.js:61
1 0.2% 0.2% Function: ~exports.log console.js:24
1 0.2% 0.2% Function: ~NativeModule node.js:558
[C++]:
ticks total nonlib name
[GC]:
ticks total nonlib name
6 1.2%
[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
187 36.9% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
187 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
187 100.0% Function: ~Module._compile module.js:372
187 100.0% Function: ~Module._extensions..js module.js:465
187 100.0% Function: ~Module.load module.js:346
187 100.0% Function: Module._load module.js:275
103 20.3% LazyCompile: *proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:334
103 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
103 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
103 100.0% Function: ~Module._compile module.js:372
103 100.0% Function: ~Module._extensions..js module.js:465
103 100.0% Function: ~Module.load module.js:346
75 14.8% LazyCompile: *parse native json.js:55
75 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
75 100.0% Function: ~Module._compile module.js:372
75 100.0% Function: ~Module._extensions..js module.js:465
75 100.0% Function: ~Module.load module.js:346
75 100.0% Function: Module._load module.js:275
21 4.1% /lib/x86_64-linux-gnu/libpthread-2.13.so
21 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
21 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
21 100.0% Function: ~Module._compile module.js:372
21 100.0% Function: ~Module._extensions..js module.js:465
21 100.0% Function: ~Module.load module.js:346
18 3.6% Function: ~NativeModule.compile node.js:613
18 100.0% Function: ~NativeModule.require node.js:568
5 27.8% Function: ~tryFile module.js:138
5 100.0% Function: ~Module._findPath module.js:160
5 100.0% Function: ~Module._resolveFilename module.js:323
5 100.0% Function: Module._load module.js:275
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: ~startup node.js:30
4 100.0% LazyCompile: ~<anonymous> node.js:27
2 11.1% Function: ~startup.globalVariables node.js:158
2 100.0% Function: ~startup node.js:30
2 100.0% LazyCompile: ~<anonymous> node.js:27
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> fs.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 100.0% Function: ~tryFile module.js:138
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/jsonparse/bench.js:1
16 3.2% Stub: StringAddStub
16 100.0% Function: proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
16 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
16 100.0% Function: ~Module._compile module.js:372
16 100.0% Function: ~Module._extensions..js module.js:465
16 100.0% Function: ~Module.load module.js:346
13 2.6% LazyCompile: ~parse native json.js:55
13 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
13 100.0% Function: ~Module._compile module.js:372
13 100.0% Function: ~Module._extensions..js module.js:465
13 100.0% Function: ~Module.load module.js:346
13 100.0% Function: Module._load module.js:275
11 2.2% /lib/x86_64-linux-gnu/libc-2.13.so
4 36.4% Function: ~NativeModule.compile node.js:613
4 100.0% Function: ~NativeModule.require node.js:568
2 50.0% Function: ~tryFile module.js:138
2 100.0% Function: ~Module._findPath module.js:160
2 100.0% Function: ~Module._resolveFilename module.js:323
1 25.0% Function: ~startup.globalVariables node.js:158
1 100.0% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
1 25.0% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
2 18.2% LazyCompile: *parse native json.js:55
2 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
2 100.0% Function: ~Module._compile module.js:372
2 100.0% Function: ~Module._extensions..js module.js:465
2 100.0% Function: ~Module.load module.js:346
1 9.1% LazyCompile: ~join native array.js:410
1 100.0% Function: ~exports.resolve path.js:279
1 100.0% Function: ~Module._initPaths module.js:495
1 100.0% LazyCompile: ~<anonymous> module.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 9.1% Function: ~proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.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 9.1% 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/jsonparse/bench.js:1
1 9.1% 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/jsonparse/bench.js:1
1 100.0% Function: ~Module._compile module.js:372Now let's do this for proto.write
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node --trace-opt --trace-bailout bench.js
[marking toLowerCase 0x678f10499e8 for recompilation, reason: small function, ICs with typeinfo: 0/2 (0%)]
[optimizing: toLowerCase / 678f10499e9 - took 0.824 ms]
[marking parse 0x678f104a4e0 for recompilation, reason: small function, ICs with typeinfo: 2/4 (50%)]
[optimizing: parse / 678f104a4e1 - took 0.133 ms]
[marking IsPrimitive 0x678f1053578 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[marking NonStringToString 0x678f1052338 for recompilation, reason: small function, ICs with typeinfo: 2/2 (100%)]
Bailout in HGraphBuilder: @"NonStringToString": call to a JavaScript runtime function
[disabled optimization for NonStringToString]
[optimizing: IsPrimitive / 678f1053579 - took 0.043 ms]
[marking Buffer.toString 0x678f1070570 for recompilation, reason: hot and stable, ICs with typeinfo: 9/37 (24%)]
[optimizing: Buffer.toString / 678f1070571 - took 0.557 ms]
[marking DefaultString 0x678f10532e8 for recompilation, reason: hot and stable, ICs with typeinfo: 2/7 (28%)]
Bailout in HGraphBuilder: @"DefaultString": call to a JavaScript runtime function
[disabled optimization for DefaultString]
[marking proto.write 0x290e5c80ac50 for recompilation, reason: hot and stable, ICs with typeinfo: 119/381 (31%)]
[optimizing: proto.write / 290e5c80ac51 - took 7.231 ms]
[marking proto.write 0x290e5c80ac50 for recompilation, reason: hot and stable, ICs with typeinfo: 149/381 (39%)]
[marking proto.onValue 0x290e5c80ae68 for recompilation, reason: small function, ICs with typeinfo: 0/0 (100%)]
[marking proto.emit 0x290e5c80ae20 for recompilation, reason: small function, ICs with typeinfo: 3/3 (100%)]
[optimizing: proto.write / 290e5c80ac51 - took 6.154 ms]
[optimizing: proto.emit / 290e5c80ae21 - took 0.132 ms]
[marking proto.onToken 0x290e5c80aeb0 for recompilation, reason: hot and stable, ICs with typeinfo: 44/80 (55%)]
[optimizing: proto.onToken / 290e5c80aeb1 - took 1.530 ms]
[optimizing: proto.onValue / 290e5c80ae69 - took 0.025 ms]
[marking proto.onToken 0x290e5c80aeb0 for recompilation, reason: hot and stable, ICs with typeinfo: 45/80 (56%)]
[optimizing: proto.onToken / 290e5c80aeb1 - took 1.212 ms]
[marking proto.pop 0x290e5c80add8 for recompilation, reason: small function, ICs with typeinfo: 12/12 (100%)]
[optimizing: proto.pop / 290e5c80add9 - took 0.132 ms]
JSON.parse took 103
streaming parser took 244
streaming is 2.3689320388349513 times slowerlbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node --prof bench.js
JSON.parse took 102
streaming parser took 253
streaming is 2.480392156862745 times slower
lbdremy@lbdremy-Latitude-E6500:~/workspace/nodejs/jsonparse$ node-tick-processor
Statistical profiling result from node, (387 ticks, 232 unaccounted, 0 excluded).
[Unknown]:
ticks total nonlib name
232 59.9%
[Shared libraries]:
ticks total nonlib name
16 4.1% 0.0% /lib/x86_64-linux-gnu/libc-2.13.so
1 0.3% 0.0% /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.16
1 0.3% 0.0% /lib/x86_64-linux-gnu/libpthread-2.13.so
[JavaScript]:
ticks total nonlib name
111 28.7% 30.1% LazyCompile: *proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:306
94 24.3% 25.5% LazyCompile: *proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
79 20.4% 21.4% LazyCompile: *parse native json.js:55
21 5.4% 5.7% Function: ~NativeModule.compile node.js:613
15 3.9% 4.1% Function: ~proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
11 2.8% 3.0% LazyCompile: ~parse native json.js:55
5 1.3% 1.4% LazyCompile: *proto.pop /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:290
4 1.0% 1.1% Stub: StringAddStub
3 0.8% 0.8% Function: ~Buffer.toString buffer.js:392
2 0.5% 0.5% Stub: CEntryStub
2 0.5% 0.5% LazyCompile: ~DefaultString native runtime.js:645
2 0.5% 0.5% KeyedStoreIC: A keyed store IC from the snapshot
1 0.3% 0.3% Stub: RecordWriteStub {2}
1 0.3% 0.3% Stub: RecordWriteStub {1}
1 0.3% 0.3% Stub: RecordWriteStub
1 0.3% 0.3% LazyCompile: ~BasicJSONSerialize native json.js:273
1 0.3% 0.3% LazyCompile: ~<anonymous> buffer.js:1
1 0.3% 0.3% LazyCompile: ~$Array.get_ native v8natives.js:550
1 0.3% 0.3% LazyCompile: InstantiateFunction native apinatives.js:65
1 0.3% 0.3% LazyCompile: *Buffer.toString buffer.js:392
1 0.3% 0.3% Function: ~createWritableStdioStream node.js:296
1 0.3% 0.3% Function: ~NativeModule.wrap node.js:604
1 0.3% 0.3% Function: ~Module._compile module.js:372
[C++]:
ticks total nonlib name
[GC]:
ticks total nonlib name
6 1.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
111 28.7% LazyCompile: *proto.onToken /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:306
111 100.0% LazyCompile: *proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
111 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
111 100.0% Function: ~Module._compile module.js:372
111 100.0% Function: ~Module._extensions..js module.js:465
111 100.0% Function: ~Module.load module.js:346
94 24.3% LazyCompile: *proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
94 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
94 100.0% Function: ~Module._compile module.js:372
94 100.0% Function: ~Module._extensions..js module.js:465
94 100.0% Function: ~Module.load module.js:346
94 100.0% Function: Module._load module.js:275
79 20.4% LazyCompile: *parse native json.js:55
79 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
79 100.0% Function: ~Module._compile module.js:372
79 100.0% Function: ~Module._extensions..js module.js:465
79 100.0% Function: ~Module.load module.js:346
79 100.0% Function: Module._load module.js:275
21 5.4% Function: ~NativeModule.compile node.js:613
21 100.0% Function: ~NativeModule.require node.js:568
9 42.9% Function: ~tryFile module.js:138
9 100.0% Function: ~Module._findPath module.js:160
9 100.0% Function: ~Module._resolveFilename module.js:323
9 100.0% Function: Module._load module.js:275
3 14.3% LazyCompile: ~<anonymous> tty.js:1
3 100.0% Function: ~NativeModule.compile node.js:613
3 100.0% Function: ~NativeModule.require node.js:568
3 100.0% Function: ~createWritableStdioStream node.js:296
3 14.3% Function: ~startup.globalVariables node.js:158
3 100.0% Function: ~startup node.js:30
3 100.0% LazyCompile: ~<anonymous> node.js:27
2 9.5% LazyCompile: ~<anonymous> buffer.js:1
2 100.0% Function: ~NativeModule.compile node.js:613
2 100.0% Function: ~NativeModule.require node.js:568
2 100.0% Function: ~startup.globalVariables node.js:158
2 9.5% Function: ~startup node.js:30
2 100.0% LazyCompile: ~<anonymous> node.js:27
1 4.8% 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 4.8% 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
16 4.1% /lib/x86_64-linux-gnu/libc-2.13.so
4 25.0% Function: ~NativeModule.compile node.js:613
4 100.0% Function: ~NativeModule.require node.js:568
1 25.0% LazyCompile: ~<anonymous> tty.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 25.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 25.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 25.0% Function: ~startup.globalVariables node.js:158
1 100.0% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
1 6.3% LazyCompile: ~exec native regexp.js:171
1 100.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 6.3% 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 100.0% LazyCompile: ~<anonymous> assert.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 6.3% LazyCompile: ~BasicSerializeArray native json.js:181
1 100.0% LazyCompile: ~BasicJSONSerialize native json.js:273
1 100.0% LazyCompile: ~stringify native json.js:307
1 100.0% Function: ~Module._resolveFilename module.js:323
1 100.0% Function: Module._load module.js:275
1 6.3% LazyCompile: ~<anonymous> fs.js:1
1 100.0% Function: ~NativeModule.compile node.js:613
1 100.0% Function: ~NativeModule.require node.js:568
1 100.0% Function: ~tryFile module.js:138
1 100.0% Function: ~Module._findPath module.js:160
1 6.3% LazyCompile: *proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.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 6.3% Function: ~startup.lazyConstants node.js:197
1 100.0% Function: ~isSignal node.js:475
1 100.0% Function: ~startup.processSignalHandlers.process.on.process.addListener node.js:480
1 100.0% Function: ~<anonymous> node.js:355
1 100.0% Function: ~exports.log console.js:24
1 6.3% Function: ~startup node.js:30
1 100.0% LazyCompile: ~<anonymous> node.js:27
1 6.3% Function: ~proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
1 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.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 6.3% 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 100.0% Function: ~Module.require module.js:361
1 6.3% 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
15 3.9% Function: ~proto.write /home/lbdremy/workspace/nodejs/jsonparse/jsonparse.js:84
15 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
15 100.0% Function: ~Module._compile module.js:372
15 100.0% Function: ~Module._extensions..js module.js:465
15 100.0% Function: ~Module.load module.js:346
15 100.0% Function: Module._load module.js:275
11 2.8% LazyCompile: ~parse native json.js:55
11 100.0% LazyCompile: ~<anonymous> /home/lbdremy/workspace/nodejs/jsonparse/bench.js:1
11 100.0% Function: ~Module._compile module.js:372
11 100.0% Function: ~Module._extensions..js module.js:465
11 100.0% Function: ~Module.load module.js:346
11 100.0% Function: Module._load module.js:275Sample of the output of bench.js now
streaming parser took 229
streaming is 2.3608247422680413 times slower
JSON.parse took 95
streaming parser took 225
streaming is 2.3684210526315788 times slower
JSON.parse took 96
streaming parser took 239
streaming is 2.4895833333333335 times slower
JSON.parse took 95
streaming parser took 224
streaming is 2.357894736842105 times slower
JSON.parse took 96
streaming parser took 225
streaming is 2.34375 times slower
JSON.parse took 96
streaming parser took 226
streaming is 2.3541666666666665 times slower
JSON.parse took 96
streaming parser took 223
streaming is 2.3229166666666665 times slower
JSON.parse took 97
streaming parser took 227
streaming is 2.3402061855670104 times slowercompared to before :
JSON.parse took 97
streaming parser took 416
streaming is 4.288659793814433 times slower
JSON.parse took 97
streaming parser took 413
streaming is 4.257731958762887 times slower
JSON.parse took 96
streaming parser took 414
streaming is 4.3125 times slower
JSON.parse took 95
streaming parser took 413
streaming is 4.347368421052631 times slower
JSON.parse took 95
streaming parser took 418
streaming is 4.4 times slower
JSON.parse took 99
streaming parser took 413
streaming is 4.171717171717172 times slower
JSON.parse took 96
streaming parser took 420
streaming is 4.375 times slowerAlmost cut by two the time spent! :)