feat: add bindings to run microtasks from Isolate #2793

bartlomieju · 2019-08-19T19:58:17Z

No description provided.

core/libdeno/deno.h

core/isolate.rs

ry · 2019-08-19T20:31:19Z

core/isolate.rs

@@ -690,6 +695,7 @@ impl Future for Isolate {
      drop(locker);
    }

+    self.run_microtasks()?;


Might need to be inside a locker scope.

It shouldn't. Lock is being acquired already within libdeno::deno_run_microtasks. We only need it on respond, because we don't create a lock in libdeno::deno_respond. It might make sense to remove LockerScope, and just add a lock to the async part of libdeno::deno_respond(We shouldn't need it for sync responses).

core/libdeno/api.cc

bartlomieju · 2019-08-20T11:48:44Z

Results

This PR

13:41 $ third_party/wrk/mac/wrk -d 10s --latency http://127.0.0.1:4555
Running 10s test @ http://127.0.0.1:4555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   204.46us  465.60us  10.14ms   95.44%
    Req/Sec    38.68k     3.56k   42.98k    89.60%
  Latency Distribution
     50%  111.00us
     75%  117.00us
     90%  168.00us
     99%    2.67ms
  777553 requests in 10.10s, 37.82MB read
Requests/sec:  76974.46
Transfer/sec:      3.74MB

Latest release:

13:47 $ third_party/wrk/mac/wrk -d 10s --latency http://127.0.0.1:4555
Running 10s test @ http://127.0.0.1:4555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   183.57us  372.93us   5.53ms   95.52%
    Req/Sec    40.72k     2.25k   44.34k    75.25%
  Latency Distribution
     50%  106.00us
     75%  111.00us
     90%  157.00us
     99%    2.46ms
  818606 requests in 10.10s, 39.81MB read
Requests/sec:  81050.03
Transfer/sec:      3.94MB

I'll profile V8 as well in the evening

bartlomieju · 2019-08-20T12:00:47Z

With check_last_exception removed, the results are more promising:

third_party/wrk/mac/wrk -d 10s --latency http://127.0.0.1:4555
Running 10s test @ http://127.0.0.1:4555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   192.76us  444.83us  12.51ms   95.73%
    Req/Sec    39.87k     2.52k   43.02k    87.00%
  Latency Distribution
     50%  109.00us
     75%  114.00us
     90%  149.00us
     99%    2.55ms
  793274 requests in 10.00s, 38.58MB read
Requests/sec:  79319.90
Transfer/sec:      3.86MB

bartlomieju · 2019-09-02T18:11:59Z

I'm not sure about this PR anymore... I still can't manage to get tests to pass even though I tried calling run_microtasks after each dynamic import operation and still deno_tcp has lower score than on master branch. We still should get better perf increase addressing #2758 and this PR introduces another discreet complexity. Opinions @ry @afinch7?

bartlomieju · 2019-09-03T21:21:32Z

I managed to figure out the problems 😅feel a bit ashamed that I couldn't figure it out before

Here are the benchmarks:

master

"req_per_sec": {
    "deno_tcp": 49435, 
    "deno_core_single": 57750, 
    "node_proxy_tcp": 21056, 
    "deno_proxy_tcp": 17669, 
    "deno_core_multi": 60796, 
    "deno_tcp_current_thread": 44114, 
    "hyper": 57055, 
    "node_tcp": 59013, 
    "deno_http": 18755, 
    "node_http": 23919, 
    "deno_proxy": 1004, 
    "node_proxy": 2785
  }, 
  "max_latency": {
    "deno_tcp": 8.7, 
    "deno_core_single": 0.359, 
    "node_proxy_tcp": 1.12, 
    "deno_proxy_tcp": 5.22, 
    "deno_core_multi": 1.15, 
    "deno_tcp_current_thread": 8.91, 
    "hyper": 3.19, 
    "node_tcp": 0.543, 
    "deno_http": 2.63, 
    "node_http": 1.97, 
    "deno_proxy": 17.71, 
    "node_proxy": 9.95
  },

this PR

  "req_per_sec": {
    "deno_tcp": 46789, 
    "deno_core_single": 48533, 
    "node_proxy_tcp": 19905, 
    "deno_proxy_tcp": 16999, 
    "deno_core_multi": 50461, 
    "deno_tcp_current_thread": 44352, 
    "hyper": 59689, 
    "node_tcp": 59066, 
    "deno_http": 13950, 
    "node_http": 23674, 
    "deno_proxy": 970, 
    "node_proxy": 2641
  }, 
  "max_latency": {
    "deno_tcp": 8.72, 
    "deno_core_single": 0.41, 
    "node_proxy_tcp": 1.19, 
    "deno_proxy_tcp": 5.66, 
    "deno_core_multi": 0.89, 
    "deno_tcp_current_thread": 8.98, 
    "hyper": 0.88, 
    "node_tcp": 0.529, 
    "deno_http": 2.89, 
    "node_http": 1.78, 
    "deno_proxy": 17.93, 
    "node_proxy": 9.97
  }

bartlomieju · 2019-09-03T21:31:29Z

Flamegraphs

master:

this PR:

ry · 2019-09-04T14:46:40Z

@bartlomieju so given the fix in #2858, is this an improvement?

bartlomieju · 2019-09-04T15:11:48Z

@ry I just checked benchmark:

third_party/wrk/mac/wrk -d 10s --latency http://127.0.0.1:4544
Running 10s test @ http://127.0.0.1:4544
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   301.58us    0.94ms  21.50ms   96.02%
    Req/Sec    31.80k     5.71k   41.25k    62.87%
  Latency Distribution
     50%  124.00us
     75%  156.00us
     90%  268.00us
     99%    4.69ms
  639117 requests in 10.10s, 31.08MB read
Requests/sec:  63266.79
Transfer/sec:      3.08MB

That's significantly slower, I'd assume that now microtasks are run too rarely.
I still want to experiment a bit running microtasks only in libdeno code. I'll get back to you.

bartlomieju · 2019-09-04T17:35:16Z

@ry so I also removed calls to LockerScope as suggested by @afinch7 here and moved calls to RunMicrotasks into deno_respond.

It looks like performance is comparable to master branch so I'm not entirely sure microtasks are bottleneck in our performance problems.

bartlomieju · 2019-09-05T10:54:42Z

Latest benchmarks

v0.17.0

  "req_per_sec": {
    "deno_tcp": 50392, 
    "deno_core_single": 51854, 
    "node_proxy_tcp": 18498, 
    "deno_proxy_tcp": 17372, 
    "deno_core_multi": 57736, 
    "deno_tcp_current_thread": 48354, 
    "hyper": 60346, 
    "node_tcp": 50332, 
    "deno_http": 17544, 
    "node_http": 19701, 
    "deno_proxy": 984, 
    "node_proxy": 2546
  }, 
  "max_latency": {
    "deno_tcp": 9.55, 
    "deno_core_single": 0.401, 
    "node_proxy_tcp": 1.14, 
    "deno_proxy_tcp": 6.17, 
    "deno_core_multi": 1.23, 
    "deno_tcp_current_thread": 10.05, 
    "hyper": 0.776, 
    "node_tcp": 0.618, 
    "deno_http": 2.95, 
    "node_http": 2.22, 
    "deno_proxy": 18.16, 
    "node_proxy": 10.43
  },

this PR

  "req_per_sec": {
    "deno_tcp": 51200, 
    "deno_core_single": 50504, 
    "node_proxy_tcp": 20413, 
    "deno_proxy_tcp": 18359, 
    "deno_core_multi": 57639, 
    "deno_tcp_current_thread": 47770, 
    "hyper": 60629, 
    "node_tcp": 59573, 
    "deno_http": 18560, 
    "node_http": 24048, 
    "deno_proxy": 959, 
    "node_proxy": 2746
  }, 
  "max_latency": {
    "deno_tcp": 8.75, 
    "deno_core_single": 0.455, 
    "node_proxy_tcp": 1.05, 
    "deno_proxy_tcp": 5.66, 
    "deno_core_multi": 1.18, 
    "deno_tcp_current_thread": 9.29, 
    "hyper": 0.732, 
    "node_tcp": 0.544, 
    "deno_http": 2.7, 
    "node_http": 2.04, 
    "deno_proxy": 18.0, 
    "node_proxy": 9.99
  },

Side note: benchmarks are fluctuating a lot, maybe we should run each benchmark 3-5 times and average the results to smooth out charts?

ry · 2019-09-05T14:08:35Z

core/isolate.rs

    }

+    //    self.run_microtasks();


You're not calling run_microtasks... I would think this will cause test failures

@ry I call isolate->RunMicrotasks() in libdeno code. Those commented bits need to be removed.

ry · 2019-09-05T14:17:06Z

core/libdeno/api.cc

@@ -198,6 +200,7 @@ void deno_respond(Deno* d_, void* user_data, deno_op_id op_id, deno_buf buf) {
  }

  auto v = recv_->Call(context, context->Global(), argc, args);
+  d->isolate_->RunMicrotasks();


I think this is the same as kAuto... I benchmarked it and there's no change

master

~/src/deno> wrk http://127.0.0.1:4500/ Running 10s test @ http://127.0.0.1:4500/ 2 threads and 10 connections Thread Stats Avg Stdev Max +/- Stdev Latency 291.26us 494.34us 11.83ms 96.74% Req/Sec 20.33k 2.10k 32.32k 82.50% 404493 requests in 10.00s, 19.67MB read Requests/sec: 40447.21 Transfer/sec: 1.97MB ~/src/deno> wrk http://127.0.0.1:4500/ Running 10s test @ http://127.0.0.1:4500/ 2 threads and 10 connections Thread Stats Avg Stdev Max +/- Stdev Latency 272.21us 386.03us 6.74ms 97.01% Req/Sec 20.61k 1.59k 24.46k 68.50% 410139 requests in 10.00s, 19.95MB read Requests/sec: 41001.46 Transfer/sec: 1.99MB

this branch

~/src/deno> wrk http://127.0.0.1:4500/ Running 10s test @ http://127.0.0.1:4500/ 2 threads and 10 connections Thread Stats Avg Stdev Max +/- Stdev Latency 272.63us 402.47us 6.44ms 97.03% Req/Sec 20.81k 1.43k 28.58k 83.17% 418073 requests in 10.10s, 20.33MB read Requests/sec: 41393.01 Transfer/sec: 2.01MB ~/src/deno> wrk http://127.0.0.1:4500/ Running 10s test @ http://127.0.0.1:4500/ 2 threads and 10 connections Thread Stats Avg Stdev Max +/- Stdev Latency 271.93us 400.53us 6.75ms 97.05% Req/Sec 20.84k 1.22k 26.85k 80.69% 418670 requests in 10.10s, 20.36MB read Requests/sec: 41454.11 Transfer/sec: 2.02MB

That's my experience as well, calling run_microtasks inside Isolate::poll gives about 10-15% less req/sec.

bartlomieju · 2019-09-12T16:16:44Z

Ping @ry @piscisaureus do you have any thoughts about this PR?

There's no perf gain from this PR and it introduces additional complexity so IMHO it's not really worth landing

ry · 2019-09-12T16:25:30Z

@bartlomieju I'd like to have the libdeno binding available for future experimentation, but left it in kAuto for now. I'd be happy to land that.

bartlomieju · 2019-09-12T16:32:28Z

@bartlomieju I'd like to have the libdeno binding available for future experimentation, but left it in kAuto for now. I'd be happy to land that.

Sure, I'll update the PR

ry

LGTM - thanks - I’m sure this will come in handy soon.

bartlomieju force-pushed the feat-explicit_microtask_policy branch from fb57c54 to 838e811 Compare August 19, 2019 19:59

ry reviewed Aug 19, 2019

View reviewed changes

core/libdeno/deno.h Outdated Show resolved Hide resolved

ry reviewed Aug 19, 2019

View reviewed changes

core/isolate.rs Outdated Show resolved Hide resolved

ry reviewed Aug 19, 2019

View reviewed changes

core/libdeno/api.cc Outdated Show resolved Hide resolved

bartlomieju mentioned this pull request Sep 4, 2019

perf: less aggresive dyn import polling #2858

Merged

ry reviewed Sep 5, 2019

View reviewed changes

bartlomieju added 9 commits September 12, 2019 18:33

use v8::MicrotaskPolicy::kExplicit

7aac23b

pass user_data to deno_run_microtasks

3b6669a

remove unneeded check

4e9a408

fmt

1242de9

run microtasks in deno_dyn_import_done

2de9349

fix libdeno tests

ebcc372

call RunMicrotasks from libdeno

5f7d86c

do not use LockerScope

8dc4df6

revert to MicrotaskPolicy::kAuto

2fc6aa5

bartlomieju force-pushed the feat-explicit_microtask_policy branch from ef53cf0 to 2fc6aa5 Compare September 12, 2019 16:36

bartlomieju changed the title ~~feat: use v8::MicrotaskPolicy::kExplicit~~ feat: add bindings to run microtasks from Isolate Sep 12, 2019

leave only binding

292f8c4

ry approved these changes Sep 12, 2019

View reviewed changes

ry merged commit c03cdcc into denoland:master Sep 12, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: add bindings to run microtasks from Isolate #2793

feat: add bindings to run microtasks from Isolate #2793

bartlomieju commented Aug 19, 2019

ry Aug 19, 2019

afinch7 Aug 20, 2019 •

edited

Loading

bartlomieju commented Aug 20, 2019

bartlomieju commented Aug 20, 2019

bartlomieju commented Sep 2, 2019

bartlomieju commented Sep 3, 2019

bartlomieju commented Sep 3, 2019 •

edited

Loading

ry commented Sep 4, 2019

bartlomieju commented Sep 4, 2019

bartlomieju commented Sep 4, 2019

bartlomieju commented Sep 5, 2019 •

edited

Loading

ry Sep 5, 2019 •

edited

Loading

bartlomieju Sep 5, 2019 •

edited

Loading

ry Sep 5, 2019

bartlomieju Sep 5, 2019

bartlomieju commented Sep 12, 2019

ry commented Sep 12, 2019

bartlomieju commented Sep 12, 2019

ry left a comment

feat: add bindings to run microtasks from Isolate #2793

feat: add bindings to run microtasks from Isolate #2793

Conversation

bartlomieju commented Aug 19, 2019

ry Aug 19, 2019

Choose a reason for hiding this comment

afinch7 Aug 20, 2019 • edited Loading

Choose a reason for hiding this comment

bartlomieju commented Aug 20, 2019

bartlomieju commented Aug 20, 2019

bartlomieju commented Sep 2, 2019

bartlomieju commented Sep 3, 2019

bartlomieju commented Sep 3, 2019 • edited Loading

Flamegraphs

ry commented Sep 4, 2019

bartlomieju commented Sep 4, 2019

bartlomieju commented Sep 4, 2019

bartlomieju commented Sep 5, 2019 • edited Loading

ry Sep 5, 2019 • edited Loading

Choose a reason for hiding this comment

bartlomieju Sep 5, 2019 • edited Loading

Choose a reason for hiding this comment

ry Sep 5, 2019

Choose a reason for hiding this comment

bartlomieju Sep 5, 2019

Choose a reason for hiding this comment

bartlomieju commented Sep 12, 2019

ry commented Sep 12, 2019

bartlomieju commented Sep 12, 2019

ry left a comment

Choose a reason for hiding this comment

afinch7 Aug 20, 2019 •

edited

Loading

bartlomieju commented Sep 3, 2019 •

edited

Loading

bartlomieju commented Sep 5, 2019 •

edited

Loading

ry Sep 5, 2019 •

edited

Loading

bartlomieju Sep 5, 2019 •

edited

Loading