Skip to content

Commit

Permalink
Perf profiling results for nodejs/node#4007
Browse files Browse the repository at this point in the history
  • Loading branch information
@Fishrock123
Fishrock123 committed Nov 30, 2015
0 parents commit 5c661ca
Show file tree
Hide file tree
Showing 8 changed files with 353 additions and 0 deletions.
1 change: 1 addition & 0 deletions pr-4007/readme.md
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
nodejs/node `master` at the time of these tests was `658842280dcbb91576fc0d568c49a9c9e3fb40c2`.
13 changes: 13 additions & 0 deletions pr-4007/template.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
testN.js on `master` with [`2ccde01...1362205`](https://github.com/Fishrock123/node/compare/2ccde01...1362205) applied.

```
wrk ...
```

```
```

Relevant `--prof` data:

```
```
86 changes: 86 additions & 0 deletions pr-4007/test1/1-master.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,86 @@
test1.js on `master`


```
wrk -t12 -c400 -d30s http://45.55.209.17:4242/
```

```
Running 30s test @ http://45.55.209.17:4242/
12 threads and 400 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 86.55ms 181.57ms 5.04s 96.54%
Req/Sec 402.71 107.60 693.00 72.36%
141047 requests in 30.00s, 13.32MB read
Socket errors: connect 0, read 0, write 0, timeout 264
Requests/sec: 4701.17
Transfer/sec: 454.51KB
```

Relevant `--prof` data:

```
Statistical profiling result from test1-1-master.log, (26719 ticks, 0 unaccounted, 0 excluded).
[JavaScript]:
ticks total nonlib name
529 2.0% 2.7% Stub: LoadICStub
329 1.2% 1.7% LazyCompile: *nextTick node.js:488:22
298 1.1% 1.5% LazyCompile: *parserOnIncoming _http_server.js:454:28
193 0.7% 1.0% KeyedLoadIC: A keyed load IC from the snapshot
182 0.7% 0.9% Stub: GrowArrayElementsStub
180 0.7% 0.9% LazyCompile: ~resOnFinish _http_server.js:490:25
180 0.7% 0.9% LazyCompile: *parserOnHeadersComplete _http_common.js:43:33
174 0.7% 0.9% LazyCompile: *emit events.js:118:44
172 0.6% 0.9% LazyCompile: *_tickCallback node.js:346:27
147 0.6% 0.7% Stub: StringAddStub_CheckNone_NotTenured
146 0.5% 0.7% LazyCompile: *OutgoingMessage.end _http_outgoing.js:527:41
130 0.5% 0.7% LazyCompile: *IncomingMessage _http_incoming.js:21:25
119 0.4% 0.6% LazyCompile: *exports._unrefActive timers.js:601:32
118 0.4% 0.6% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
116 0.4% 0.6% LazyCompile: *OutgoingMessage _http_outgoing.js:47:25
112 0.4% 0.6% LazyCompile: doNTCallbackMany node.js:471:30
112 0.4% 0.6% LazyCompile: *OutgoingMessage._storeHeader _http_outgoing.js:191:50
[Summary]:
ticks total nonlib name
8343 31.2% 42.1% JavaScript
11496 43.0% 57.9% C++
150 0.6% 0.8% GC
6880 25.7% Shared libraries
[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
5723 21.4% /lib/x86_64-linux-gnu/libpthread-2.21.so
3633 63.5% LazyCompile: *Socket._writeGeneric net.js:623:42
3633 100.0% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
3633 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
3633 100.0% LazyCompile: *OutgoingMessage._send _http_outgoing.js:123:43
3633 100.0% LazyCompile: *OutgoingMessage.end _http_outgoing.js:527:41
617 10.8% LazyCompile: *createWriteReq net.js:698:24
617 100.0% LazyCompile: ~Socket._writeGeneric net.js:623:42
612 99.2% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
612 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
612 100.0% LazyCompile: *OutgoingMessage._send _http_outgoing.js:123:43
2467 9.2% syscall
885 3.3% [vdso]
704 79.5% LazyCompile: *exports._unrefActive timers.js:601:32
z
610 86.6% LazyCompile: *Socket._writeGeneric net.js:623:42
610 100.0% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
610 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
610 100.0% LazyCompile: *OutgoingMessage._send _http_outgoing.js:123:43
79 11.2% LazyCompile: *unrefTimer net.js:176:51
79 100.0% LazyCompile: ~Socket._writeGeneric net.js:623:42
79 100.0% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
79 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
```
85 changes: 85 additions & 0 deletions pr-4007/test1/1-refactor-timers.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,85 @@
test1.js on `master` with [`2ccde01...1362205`](https://github.com/Fishrock123/node/compare/2ccde01...1362205) applied.

```
wrk -t12 -c400 -d30s http://45.55.209.17:4242/
```

```
Running 30s test @ http://45.55.209.17:4242/
12 threads and 400 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 82.85ms 94.24ms 1.04s 96.58%
Req/Sec 397.22 103.15 783.00 72.96%
139481 requests in 30.00s, 13.17MB read
Socket errors: connect 0, read 0, write 0, timeout 273
Requests/sec: 4648.92
Transfer/sec: 449.46KB
```

Relevant `--prof` data:

```
Statistical profiling result from test1-2-master.log, (26881 ticks, 1 unaccounted, 0 excluded).
[JavaScript]:
ticks total nonlib name
514 1.9% 2.5% Stub: LoadICStub
331 1.2% 1.6% LazyCompile: *nextTick node.js:488:22
286 1.1% 1.4% LazyCompile: *parserOnIncoming _http_server.js:454:28
263 1.0% 1.3% LazyCompile: *emit events.js:118:44
212 0.8% 1.0% KeyedLoadIC: A keyed load IC from the snapshot
193 0.7% 0.9% LazyCompile: ~resOnFinish _http_server.js:490:25
165 0.6% 0.8% LazyCompile: *_tickCallback node.js:346:27
157 0.6% 0.8% LazyCompile: ~insert timers.js:73:16
149 0.6% 0.7% LazyCompile: *parserOnHeadersComplete _http_common.js:43:33
146 0.5% 0.7% LazyCompile: *Socket._writeGeneric net.js:623:42
131 0.5% 0.6% Stub: GrowArrayElementsStub
123 0.5% 0.6% LazyCompile: INSTANCE_OF native runtime.js:289:21
123 0.5% 0.6% LazyCompile: *OutgoingMessage.end _http_outgoing.js:527:41
123 0.5% 0.6% LazyCompile: *OutgoingMessage _http_outgoing.js:47:25
119 0.4% 0.6% Stub: StringAddStub_CheckNone_NotTenured
118 0.4% 0.6% LazyCompile: *IncomingMessage _http_incoming.js:21:25
111 0.4% 0.5% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
110 0.4% 0.5% LazyCompile: *Readable.read _stream_readable.js:251:35
109 0.4% 0.5% LazyCompile: *OutgoingMessage._storeHeader _http_outgoing.js:191:50
108 0.4% 0.5% LazyCompile: *Stream stream.js:23:16
[Summary]:
ticks total nonlib name
8556 31.8% 41.4% JavaScript
12103 45.0% 58.6% C++
129 0.5% 0.6% GC
6221 23.1% Shared libraries
1 0.0% Unaccounted
[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
5637 21.0% /lib/x86_64-linux-gnu/libpthread-2.21.so
3620 64.2% LazyCompile: *Socket._writeGeneric net.js:623:42
3620 100.0% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
3620 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
3620 100.0% LazyCompile: *OutgoingMessage._send _http_outgoing.js:123:43
3620 100.0% LazyCompile: *OutgoingMessage.end _http_outgoing.js:527:41
483 8.6% LazyCompile: *createWriteReq net.js:698:24
483 100.0% LazyCompile: ~Socket._writeGeneric net.js:623:42
483 100.0% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
483 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
483 100.0% LazyCompile: *OutgoingMessage._send _http_outgoing.js:123:43
2176 8.1% syscall
560 2.1% node::TimerWrap::Now(v8::FunctionCallbackInfo<v8::Value> const&)
557 99.5% v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
557 100.0% LazyCompile: ~insert timers.js:73:16
548 98.4% LazyCompile: *Socket._writeGeneric net.js:623:42
548 100.0% LazyCompile: *writeOrBuffer _stream_writable.js:256:23
548 100.0% LazyCompile: *OutgoingMessage._writeRaw _http_outgoing.js:146:47
```
8 changes: 8 additions & 0 deletions pr-4007/test1/test1.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
var http = require('http');
var server = http.createServer(function (req, res) {
res.end();
})

server.listen(4242, function() {
console.log('Server listening on port 4242...');
});
71 changes: 71 additions & 0 deletions pr-4007/test2/1-master.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,71 @@
test2.js on `master`

```
wrk -t12 -c10000 -d30s http://45.55.209.17:4242/
```

```
Running 30s test @ http://45.55.209.17:4242/
12 threads and 10000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 0.00us 0.00us 0.00us nan%
Req/Sec 0.00 0.00 0.00 nan%
0 requests in 30.07s, 0.00B read
Socket errors: connect 7451, read 5689, write 0, timeout 146714
Requests/sec: 0.00
Transfer/sec: 0.00B
```

Relevant `--prof` data:

```
Statistical profiling result from test2-1-master.log, (11068 ticks, 0 unaccounted, 0 excluded).
[JavaScript]:
ticks total nonlib name
138 1.2% 1.3% LazyCompile: *unrefTimeout timers.js:533:22
46 0.4% 0.4% Stub: LoadICStub
32 0.3% 0.3% KeyedLoadIC: A keyed load IC from the snapshot
31 0.3% 0.3% LazyCompile: *emit events.js:118:44
20 0.2% 0.2% LazyCompile: ~Socket._destroy net.js:437:37
17 0.2% 0.2% Stub: InstanceofStub
15 0.1% 0.1% KeyedStoreIC: A keyed store IC from the snapshot
13 0.1% 0.1% LazyCompile: ~parserOnIncoming _http_server.js:454:28
13 0.1% 0.1% LazyCompile: *addListener events.js:192:58
12 0.1% 0.1% LazyCompile: *connectionListener _http_server.js:262:28
12 0.1% 0.1% LazyCompile: *Socket net.js:110:16
12 0.1% 0.1% LazyCompile: *EventEmitter events.js:6:22
[Summary]:
ticks total nonlib name
1008 9.1% 9.3% JavaScript
9824 88.8% 90.7% C++
125 1.1% 1.2% GC
236 2.1% Shared libraries
[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
8292 74.9% syscall
311 2.8% node::HandleWrap::Close(v8::FunctionCallbackInfo<v8::Value> const&)
311 100.0% v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
311 100.0% LazyCompile: ~Socket._destroy net.js:437:37
294 94.5% LazyCompile: *Socket.destroy net.js:494:36
278 94.6% LazyCompile: ~<anonymous> _http_server.js:306:32
211 75.9% LazyCompile: *emit events.js:118:44
67 24.1% LazyCompile: ~emitNone events.js:66:18
16 5.4% LazyCompile: ~onSocketFinish net.js:187:24
16 100.0% LazyCompile: *emit events.js:118:44
17 5.5% LazyCompile: ~Socket.destroy net.js:494:36
11 64.7% LazyCompile: ~onSocketFinish net.js:187:24
10 90.9% LazyCompile: *emit events.js:118:44
1 9.1% LazyCompile: ~emitNone events.js:66:18
6 35.3% LazyCompile: ~<anonymous> _http_server.js:306:32
6 100.0% LazyCompile: *emit events.js:118:44
```
78 changes: 78 additions & 0 deletions pr-4007/test2/1-refactor-timers.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,78 @@
test2.js on `master` with [`2ccde01...1362205`](https://github.com/Fishrock123/node/compare/2ccde01...1362205) applied.

```
wrk -t12 -c10000 -d30s http://45.55.209.17:4242/
```

```
Running 30s test @ http://45.55.209.17:4242/
12 threads and 10000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 0.00us 0.00us 0.00us nan%
Req/Sec 0.00 0.00 0.00 nan%
0 requests in 30.05s, 0.00B read
Socket errors: connect 7451, read 5777, write 0, timeout 146576
Requests/sec: 0.00
Transfer/sec: 0.00B
```

Relevant `--prof` data:

```
Statistical profiling result from test2-1-refactor-timers.log, (12029 ticks, 1 unaccounted, 0 excluded).
[JavaScript]:
ticks total nonlib name
32 0.3% 0.3% Stub: LoadICStub
27 0.2% 0.2% KeyedLoadIC: A keyed load IC from the snapshot {1}
25 0.2% 0.2% LazyCompile: *Socket net.js:110:16
22 0.2% 0.2% LazyCompile: ~insert timers.js:73:16
18 0.1% 0.2% LazyCompile: ~Socket._destroy net.js:437:37
17 0.1% 0.1% Stub: InstanceofStub
17 0.1% 0.1% LazyCompile: ~parserOnIncoming _http_server.js:454:28
17 0.1% 0.1% LazyCompile: *emit events.js:118:44
17 0.1% 0.1% LazyCompile: *connectionListener _http_server.js:262:28
14 0.1% 0.1% LazyCompile: ~emit events.js:118:44
14 0.1% 0.1% LazyCompile: *addListener events.js:192:58
14 0.1% 0.1% LazyCompile: *Readable.on _stream_readable.js:665:33
...
7 0.1% 0.1% LazyCompile: *remove internal/linkedlist.js:29:16
6 0.0% 0.1% LazyCompile: ~append internal/linkedlist.js:45:16
[Summary]:
ticks total nonlib name
954 7.9% 8.1% JavaScript
10850 90.2% 91.9% C++
118 1.0% 1.0% GC
224 1.9% Shared libraries
1 0.0% Unaccounted
[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
8696 72.3% syscall
332 2.8% node::HandleWrap::Close(v8::FunctionCallbackInfo<v8::Value> const&)
331 99.7% v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
331 100.0% LazyCompile: ~Socket._destroy net.js:437:37
309 93.4% LazyCompile: *Socket.destroy net.js:494:36
297 96.1% LazyCompile: ~<anonymous> _http_server.js:306:32
191 64.3% LazyCompile: *emit events.js:118:44
106 35.7% LazyCompile: *emitNone events.js:66:18
12 3.9% LazyCompile: ~onSocketFinish net.js:187:24
12 100.0% LazyCompile: *emit events.js:118:44
22 6.6% LazyCompile: ~Socket.destroy net.js:494:36
14 63.6% LazyCompile: ~<anonymous> _http_server.js:306:32
6 42.9% LazyCompile: ~emitNone events.js:66:18
5 35.7% LazyCompile: *emit events.js:118:44
3 21.4% LazyCompile: *emitNone events.js:66:18
8 36.4% LazyCompile: ~onSocketFinish net.js:187:24
8 100.0% LazyCompile: *emit events.js:118:44
```
11 changes: 11 additions & 0 deletions pr-4007/test2/test2.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
var http = require('http');
var reqIndex = 0;

var server = http.createServer(function (req, res) {
reqIndex++;
req.setTimeout(reqIndex, function() { });
});

server.listen(4242, function() {
console.log('Server listening on port 4242...');
});

0 comments on commit 5c661ca

Please sign in to comment.