dgram: call send callback asynchronously #1313

yosuke-furukawa · 2015-04-01T15:02:26Z

According to this issue #486, every callbacks should be called asynchronously, But dgram.send callback is not called asynchronously.

We can not run full benchmark test. benchmark/net/dgram.js uses send callback recursively.
But send callback is not asynchronous, the recursive callback goes infinite loop.

If this fix is accepted, we could run full benchmark test on every release.

I think libuv changes the uv_udp_send API on this commit libuv/libuv@4189122.

So I just fixed callback asynchronously using setImmediate.

Fishrock123 · 2015-04-01T15:18:53Z

R=@bnoordhuis

(also, this may be semver-major, like process.send)

brendanashworth · 2015-04-03T01:24:40Z

I vote for bug fix, as it was once asynchronous and we just didn't notice the regression (?).

yosuke-furukawa · 2015-04-03T05:20:44Z

@brendanashworth I agree with that.
Node.js v0.10 works fine. But Node.js v0.11 doesn't.
IMO, this pull request is for bug fix. this change does not break compatibility, all existing tests are green.

brendanashworth · 2015-04-03T05:30:30Z

I feel like a fix for this should belong in libuv rather than io.js, it feels rather hacky, as I don't believe we do this for any other libuv bindings. Plus, it was a commit in libuv that caused this regression, thoughts?

yosuke-furukawa · 2015-04-03T10:50:02Z

"every callback should be asynchronous" is a rule for Node/io.js (#486 (comment)). libuv does not have the rule.

According to the libuv pull request joyent/libuv#1358, this change is to improve UDP request performance. So, this is not regression for libuv.

trevnorris · 2015-04-03T21:04:04Z

lib/dgram.js

+  var self = this;
+  setImmediate(function() {
+    self.callback(err, self.length);
+  });


Hm. Would there still be the same problem if you used process.nextTick()?

I tried earlier today. setImmediate() works but process.nextTick() still hangs.

From some ad hoc testing I got the impression that the event loop is making some progress - i.e. it's not that dgram.send() is truly synchronous - but it's not making enough progress for the setTimeout timer in benchmark/net/dgram.js to fire.

trevnorris · 2015-04-03T21:04:39Z

Agreed this is a bug fix. The callback should have always been called asynchronously, and there's no API dependency requiring the order in which the callback is called.

bnoordhuis · 2015-04-03T21:16:00Z

test/parallel/test-dgram-send-callback-recursive.js

+    throw new Error('infinite loop detected');
+  }
+  if (received < limit) {
+    client.send(chunk, 0, chunk.length, common.PORT, common.localhostIPv4, onsend);


Sorry to be that guy but can you wrap this line at 80 columns?

bnoordhuis · 2015-04-03T21:21:00Z

LGTM with style nits. The issue of why dgram behaves this way needs further investigation because I couldn't quite figure it out earlier today. What I observed is this:

io.js uses uv_udp_send (not uv_udp_try_send) and that function always defers the callback, even if the write succeeds immediately.
Still, the event loop doesn't make enough progress for the timer in the benchmark to fire.

bnoordhuis · 2015-04-03T21:31:01Z

I think I had a moment of rubber duck debugging just there, I think I figured it out. :-)

uv_udp_send() pushes the request onto the completed queue when the write succeeds (which is nearly always.) The first time the callback fires:

Libuv loops over the write requests in the completed queue.
For every request, it hands it off to io.js
io.js calls into JS land
JS land calls uv_udp_send() again (dgram.send())
The write succeed immediately and uv_udp_send() pushes the request onto the completed queue, the same queue it's currently iterating over.

I think this qualifies as a libuv bug. /cc @saghul

bnoordhuis · 2015-04-03T22:10:44Z

For the record, the patch below fixes (what is effectively) the infinite loop.

diff --git a/deps/uv/src/unix/udp.c b/deps/uv/src/unix/udp.c
index 941c0ae..177ad43 100644
--- a/deps/uv/src/unix/udp.c
+++ b/deps/uv/src/unix/udp.c
@@ -133,10 +133,8 @@ static void uv__udp_io(uv_loop_t* loop, uv__io_t* w, unsigned int revents) {
   if (revents & UV__POLLIN)
     uv__udp_recvmsg(handle);

-  if (revents & UV__POLLOUT) {
+  if (revents & UV__POLLOUT)
     uv__udp_sendmsg(handle);
-    uv__udp_run_completed(handle);
-  }
 }

saghul · 2015-04-04T06:21:17Z

Yeah, I think it does qualify as a libuv bug. Can you open an issue for it?
(Sorry, I'm traveling and on mobile right now)
On Apr 3, 2015 23:11, "Ben Noordhuis" notifications@github.com wrote:

For the record, the patch below fixes (what is effectively) the infinite
loop.

diff --git a/deps/uv/src/unix/udp.c b/deps/uv/src/unix/udp.c
index 941c0ae..177ad43 100644--- a/deps/uv/src/unix/udp.c+++ b/deps/uv/src/unix/udp.c@@ -133,10 +133,8 @@ static void uv__udp_io(uv_loop_t* loop, uv__io_t* w, unsigned int revents) {
if (revents & UV__POLLIN)
uv__udp_recvmsg(handle);

if (revents & UV__POLLOUT) {+ if (revents & UV__POLLOUT)
uv__udp_sendmsg(handle);- uv__udp_run_completed(handle);- }
}

—
Reply to this email directly or view it on GitHub
#1313 (comment).

bnoordhuis · 2015-04-04T10:32:13Z

Done: libuv/libuv#301

yosuke-furukawa · 2015-04-04T11:05:27Z

Thank you @bnoordhuis !!

I fixed a test as you reviewed.

And I tried to apply the patch, but I got some Timeout errors on the io.js test.

=== release test-dgram-send-callback-buffer-length ===
Path: parallel/test-dgram-send-callback-buffer-length
/Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-send-callback-buffer-length.js:26
  throw new Error('Timeout');
        ^
Error: Timeout
    at null._onTimeout (/Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-send-callback-buffer-length.js:26:9)
    at Timer.listOnTimeout (timers.js:89:15)
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-send-callback-buffer-length.js
=== release test-cluster-dgram-1 ===
Path: parallel/test-cluster-dgram-1
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-cluster-dgram-1.js
--- TIMEOUT ---
=== release test-dgram-bytes-length ===
Path: parallel/test-dgram-bytes-length
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-bytes-length.js
--- TIMEOUT ---
=== release test-dgram-exclusive-implicit-bind ===
Path: parallel/test-dgram-exclusive-implicit-bind
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-exclusive-implicit-bind.js
--- TIMEOUT ---
=== release test-dgram-msgsize ===
Path: parallel/test-dgram-msgsize
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-msgsize.js
--- TIMEOUT ---
=== release test-dgram-pingpong ===
Path: parallel/test-dgram-pingpong
server listening on 13048 undefined
Client sending to 13048, localhost PING
server listening on 13047 localhost
Client sending to 13047, localhost PING
server listening on 13046 localhost
Client sending to 13046, localhost PING
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-pingpong.js
--- TIMEOUT ---
=== release test-dgram-send-callback-recursive ===
Path: parallel/test-dgram-send-callback-recursive
Command: out/Release/iojs /Users/yosuke/go/src/github.com/yosuke-furukawa/fork/io.js/test/parallel/test-dgram-send-callback-recursive.js
--- TIMEOUT ---

bnoordhuis · 2015-04-04T16:27:47Z

Sorry, I should have made clear that I don't consider that patch a proper fix, it's just to demonstrate that the uv__udp_run_completed() call causes the issue.

The PR LGTM but I suggest that in the commit log you explain what the issue is and that it's a temporary fix until libuv/libuv#301 is resolved.

brendanashworth · 2015-05-10T00:36:11Z

@yosuke-furukawa ping on a merge

yosuke-furukawa · 2015-05-10T01:12:54Z

oops, I will merge it soon.

dgram#send callback was changed synchronously. The PR-URL is here joyent/libuv#1358 This commit is temporary fix until libuv issue is resolved. libuv/libuv#301 PR-URL: #1313 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

yosuke-furukawa · 2015-05-10T03:12:07Z

Landed on 18d457b
Thank you for review.

Fishrock123 · 2015-05-11T20:24:21Z

This test case fails on our CI. Please make sure to run things like this on the CI before landing. :)

https://jenkins-iojs.nodesource.com/view/iojs/job/iojs+any-pr+multi/657/nodes=osx1010/tapTestReport/test.tap-153/

https://jenkins-iojs.nodesource.com/view/iojs/job/iojs+any-pr+multi/657/nodes=win2012r2/tapTestReport/test.tap-153/

https://jenkins-iojs.nodesource.com/view/iojs/job/iojs+any-pr+multi/657/nodes=win2008r2/tapTestReport/test.tap-153/

not ok 153 - test-dgram-send-callback-recursive.js
# c:\workspace\iojs+any-pr+multi\nodes\win2012r2\test\parallel\test-dgram-send-callback-recursive.js:14
# throw new Error('infinite loop detected');
# ^
# Error: infinite loop detected
# at SendWrap.onsend [as callback] (c:\workspace\iojs+any-pr+multi\nodes\win2012r2\test\parallel\test-dgram-send-callback-recursive.js:14:11)
# at Immediate._onImmediate (dgram.js:342:10)
# at processImmediate [as _immediateCallback] (timers.js:368:17)

PR-URL: nodejs#1679 Notable Changes: * win,node-gyp: the delay-load hook for windows addons has now been correctly enabled by default, it had wrongly defaulted to off in the release version of 2.0.0 (Bert Belder) nodejs#1433 * os: tmpdir()'s trailing slash stripping has been refined to fix an issue when the temp directory is at '/'. Also considers which slash is used by the operating system. (cjihrig) nodejs#1673 * tls: default ciphers have been updated to use gcm and aes128 (Mike MacCana) nodejs#1660 * build: v8 snapshots have been re-enabled by default as suggested by the v8 team, since prior security issues have been resolved. This should give some perf improvements to both startup and vm context creation. (Trevor Norris) nodejs#1663 * src: fixed preload modules not working when other flags were used before --require (Yosuke Furukawa) nodejs#1694 * dgram: fixed send()'s callback not being asynchronous (Yosuke Furukawa) nodejs#1313 * readline: emitKeys now keeps buffering data until it has enough to parse. This fixes an issue with parsing split escapes. (Alex Kocharin) * cluster: works now properly emit 'disconnect' to cluser.worker (Oleg Elifantiev) nodejs#1386 events: uncaught errors now provide some context (Evan Lucas) nodejs#1654

dgram#send callback was changed synchronously. The PR-URL is here joyent/libuv#1358 This commit is temporary fix until libuv issue is resolved. libuv/libuv#301 PR-URL: nodejs#1313 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

Revert "dgram: call send callback asynchronously" partially, since the fix is now done in libuv. Refs: nodejs#1313 Refs: libuv/libuv#371

Revert "dgram: call send callback asynchronously" partially, since the fix is now done in libuv. Refs: #1313 Refs: libuv/libuv#371 PR-URL: #1889 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Fishrock123 added the dgram Issues and PRs related to the dgram subsystem / UDP. label Apr 1, 2015

yosuke-furukawa mentioned this pull request Apr 3, 2015

benchmark: disable dgram benchmark #1258

Closed

trevnorris reviewed Apr 3, 2015
View reviewed changes

bnoordhuis reviewed Apr 3, 2015
View reviewed changes

bnoordhuis mentioned this pull request Apr 4, 2015

udp: callbacks are effectively synchronous libuv/libuv#301

Closed

dgram: call send callback asynchronously

2b1ea20

chrisdickinson added the land-on-master label Apr 17, 2015

yosuke-furukawa closed this May 10, 2015

evanlucas mentioned this pull request May 11, 2015

Random test failures in test/parallel/test-dgram-send-callback-recursive.js #1675

Closed

Fishrock123 mentioned this pull request May 12, 2015

Release proposal: v2.0.2 #1679

Merged

saghul added a commit to saghul/node that referenced this pull request Jun 3, 2015

dgram: partially revert 18d457b

7456692

Revert "dgram: call send callback asynchronously" partially, since the fix is now done in libuv. Refs: nodejs#1313 Refs: libuv/libuv#371

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

dgram: call send callback asynchronously #1313

dgram: call send callback asynchronously #1313

yosuke-furukawa commented Apr 1, 2015

Fishrock123 commented Apr 1, 2015

brendanashworth commented Apr 3, 2015

yosuke-furukawa commented Apr 3, 2015

brendanashworth commented Apr 3, 2015

yosuke-furukawa commented Apr 3, 2015

trevnorris Apr 3, 2015

bnoordhuis Apr 3, 2015

trevnorris commented Apr 3, 2015

bnoordhuis Apr 3, 2015

bnoordhuis commented Apr 3, 2015

bnoordhuis commented Apr 3, 2015

bnoordhuis commented Apr 3, 2015

saghul commented Apr 4, 2015

bnoordhuis commented Apr 4, 2015

yosuke-furukawa commented Apr 4, 2015

bnoordhuis commented Apr 4, 2015

brendanashworth commented May 10, 2015

yosuke-furukawa commented May 10, 2015

yosuke-furukawa commented May 10, 2015

Fishrock123 commented May 11, 2015

dgram: call send callback asynchronously #1313

dgram: call send callback asynchronously #1313

Conversation

yosuke-furukawa commented Apr 1, 2015

Fishrock123 commented Apr 1, 2015

brendanashworth commented Apr 3, 2015

yosuke-furukawa commented Apr 3, 2015

brendanashworth commented Apr 3, 2015

yosuke-furukawa commented Apr 3, 2015

trevnorris Apr 3, 2015

Choose a reason for hiding this comment

bnoordhuis Apr 3, 2015

Choose a reason for hiding this comment

trevnorris commented Apr 3, 2015

bnoordhuis Apr 3, 2015

Choose a reason for hiding this comment

bnoordhuis commented Apr 3, 2015

bnoordhuis commented Apr 3, 2015

bnoordhuis commented Apr 3, 2015

saghul commented Apr 4, 2015

bnoordhuis commented Apr 4, 2015

yosuke-furukawa commented Apr 4, 2015

bnoordhuis commented Apr 4, 2015

brendanashworth commented May 10, 2015

yosuke-furukawa commented May 10, 2015

yosuke-furukawa commented May 10, 2015

Fishrock123 commented May 11, 2015