DHT Request pipelining #92

vyzo · 2017-09-17T09:22:17Z

The big lock, shared by SendMessage and SendRequest, restricts our ability to issue pipelined requests with potentially significant performance impact -- #88

This patch implants a goroutine pump for serializing message reads out of line. This allows us to lock only for the duration of the write, which pipelines concurrent requests.

vyzo · 2017-09-17T09:22:42Z

Summoning @whyrusleeping @Stebalien

vyzo · 2017-09-17T10:26:41Z

Note that there is some subtlety in the fallback to the single request per stream protocol: the single message counter is only incremented in the case of a successful request.

In the case of pipelined requests failing in the read, some of them (if there is more than 2) may fail in their retries due to the old protocol while we are collecting enough samples to fallback.
We can accelerate the convergence by having read errors in retry increment the single message counter.

vyzo · 2017-09-20T07:17:38Z

Rebased on master for #93

Stebalien · 2017-09-18T17:27:13Z

dht_net.go

+		select {
+		case res = <-resch:
+
+		case <-t.C:


I'd just add a deadline to the context.

good point, will do.

we do lose the ability to distinguish ErrReadTimeount however.

You should be able to learn why this failed from ctx.Err().

right, that's what I return now -- it's just not ErrReadTimeout anymore but rather "context deadline exceeded".

Stebalien · 2017-09-18T17:47:48Z

dht_net.go

+	defer s.Close()
+
+	w := ggio.NewDelimitedWriter(s)
+	return w.WriteMsg(pmes)


This should probably reset the stream on error instead of closing it (probably not that important but generally a good idea).

Note: It's safe to close the stream after resetting it (so you can leave the defer s.Close()).

sure, small thing to fix.

Stebalien · 2017-09-18T17:50:23Z

dht_net.go

 	case <-t.C:
-		return ErrReadTimeout
+		return nil, ErrReadTimeout


Again, I'd switch to a context deadline (not your code but easy cleanup).

Stebalien · 2017-09-20T22:07:54Z

dht_net.go

-	ms.r = ggio.NewDelimitedReader(nstr, inet.MessageSizeMax)
+	r := ggio.NewDelimitedReader(nstr, inet.MessageSizeMax)
+	rch := make(chan chan requestResult, requestResultBuffer)
+	go messageReceiver(ms.dht.ctx, rch, r)


We could save on long-running go routines by starting these only as needed and shutting them down when we have no more outstanding replies (i.e., by having some form of outstanding reply counter). If we don't keep these around, we could also afford to spin up a second goroutine to manage the outstanding requests.

In general, I'm not a fan of pipelining but out-of-order replies would require a protocol change.

Lazily spinning the goroutine is perhaps not so hard to implement, but shutting it down gets tricky -- not sure its worth the complexity. Let me think about it.

whyrusleeping · 2017-09-21T21:12:11Z

dht_net.go

 		}

 		return nil
 	}
 }

 func (ms *messageSender) SendRequest(ctx context.Context, pmes *pb.Message) (*pb.Message, error) {
-	ms.lk.Lock()
-	defer ms.lk.Unlock()
+	defer log.EventBegin(ctx, "dhtSendRequest", ms.dht.self, ms.p, pmes).Done()


dont technically need to prefix the event type with "dht", the log object is created as a logger for the dht subsystem

ipfs log only gives you the event name in the event field, so that's kind of necessary to disambiguate events.

i mean for practical purposes with grep, otherwise the system field does it just fine.

I will remove the prefix, the canonical way to process the event log is jq; and grep becomes only slightly more complicated, it can be a double grep for dht and then SendRequest

whyrusleeping · 2017-09-21T21:19:32Z

dht_net.go

+		case res = <-resch:
+
+		case <-rctx.Done():
+			return nil, rctx.Err()


If the context is cancelled, do we want to kill off the stream? or is that handled elsewhere?

This is the specific request context, so it's inappropriate to kill for the entire stream.

Thinking a bit more about this, I think we do want to kill the whole stream after all.
The issue is that if we start having slow responses (over 1m), the pipeline will fill with everything timing out and become unusable until the responses are received (regardless of whether we have stopped waiting).

Will implement with a "reset" directive to the message receiver.

whyrusleeping · 2017-09-21T21:27:46Z

dht_net.go

+		case next, ok = <-rch:
+			if !ok {
+				return
+			}


This might be a little cleaner if we move the logic at the bottom of the loop into this case. Would save us from having to pre-declare those variables

ok, was just trying to avoid excessive indentation.

whyrusleeping · 2017-09-21T21:39:51Z

This tenatively looks good to me, I'd like to see some tests added that exercise some of the different scenarios (single vs pipelined, slow handlers).

How complicated this is getting makes me think we should make a new DHT protocol handler (version bump) that has message IDs in the protobuf (which should simplify this significantly). Then in the future when we have a 1.0 release, we can drop the old code. Really, this should have been just using a message based interface from the get-go.

cc @Stebalien

vyzo · 2017-09-22T08:01:01Z

I will add some more tests as these are important cases we want to make sure we handle right. I am testing with a live node for now.

Re: message ids: Yes, that would make the pump goroutine completely unnecessary and let us handle it with just two locks (read and write) and a ~~queue~~ map (for messages read out of order in the contention).

vyzo · 2017-09-22T08:15:44Z

Some analysis of performance in concurrent requests:

go-ipfs master, without pipelining:

{"event":"findPeerSingleBegin","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T08:32:30.917943022Z"}
{"event":"findPeerSingleBegin","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T08:32:30.918892911Z"}
{"event":"findPeerSingleBegin","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T08:32:30.920377591Z"}
{"duration":157141601,"event":"findPeerSingle","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T08:32:31.076695602Z"}
{"duration":313461714,"event":"findPeerSingle","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T08:32:31.231225466Z"}
{"duration":509875531,"event":"findPeerSingle","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T08:32:31.428626557Z"}

with request pipelining:

{"event":"findPeerSingleBegin","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T14:54:58.09138292Z"}
{"event":"findPeerSingleBegin","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T14:54:58.091476318Z"}
{"event":"findPeerSingleBegin","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T14:54:58.09169362Z"}
{"duration":107551379,"event":"findPeerSingle","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T14:54:58.199282563Z"}
{"duration":175856230,"event":"findPeerSingle","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T14:54:58.267292144Z"}
{"duration":256608137,"event":"findPeerSingle","peerID":"QmdFJrz6FXQU15UVCV1Evs4Ftq8xVvAtxfacC23cXySpQZ","system":"dht","time":"2017-09-21T14:54:58.348002273Z"}

whyrusleeping · 2017-10-14T14:14:54Z

@vyzo update here?

vyzo · 2017-10-14T17:42:56Z

will get back to it soon.

whyrusleeping · 2017-10-17T17:34:22Z

whoops, sorry.

rebase artifact...

vyzo · 2018-09-06T09:35:53Z

So i have rebased this, but I don't know what this business with the delayed tests is.
Another artifact of the rebase is that the bufferedDelimtedWriter use has disappeared -- i don't know what this business is either; this will need to be repatched in.

bigs · 2018-09-06T21:37:56Z

@vyzo yeah, that's the same situation i've run into. anything i can assist with?

vyzo · 2018-09-07T06:44:03Z

@bigs can you repatch in the buffered writer stuff? Seems like this is important.

Stebalien · 2018-09-12T18:34:09Z

So i have rebased this, but I don't know what this business with the delayed tests is.

@laser was trying to test network latency. The first attempt, using delayed blockstores, wasn't really sufficient. Later tests used the mocknet but I don't think they ever really removed the delayed datastore stuff (we can probably get rid of that).

raulk · 2019-02-11T16:10:16Z

@anacrolix – were you intending to review this PR? We need to merge master into it. The conflicts don't look too bad.

anacrolix · 2019-02-11T23:50:27Z

I'll try to get on to this now.

anacrolix · 2019-02-13T06:15:11Z

I've been poking around this code in master. Why don't we just send a single request per stream?

whyrusleeping · 2019-02-13T08:01:09Z

@anacrolix because opening a new stream is expensive right now. Once we get multistream 2, we can just do that.

Stebalien · 2019-02-13T17:42:51Z

See: #167

anacrolix · 2019-02-20T23:30:34Z

I am experimenting with an alternative to this, that optimistically reuses streams, and creates new ones if they're blocked. I believe it won't suffer from pipelining issues, and cross-polluting timeouts etc.

Stebalien · 2020-05-29T17:39:33Z

The DHT code has moved on and this would need to be re-implemented.

vyzo force-pushed the feat/request-pipeline branch 2 times, most recently from c0e98e4 to c4f4864 Compare September 17, 2017 10:21

vyzo force-pushed the feat/request-pipeline branch 2 times, most recently from eb0cd02 to a4ee75c Compare September 17, 2017 10:57

vyzo requested review from whyrusleeping and Stebalien September 17, 2017 11:11

vyzo mentioned this pull request Sep 19, 2017

fix memory leak holding onto streams unnecessarily #93

Merged

vyzo force-pushed the feat/request-pipeline branch from 1f9fe55 to c98efab Compare September 20, 2017 07:21

Stebalien reviewed Sep 20, 2017

View reviewed changes

whyrusleeping reviewed Sep 21, 2017

View reviewed changes

vyzo mentioned this pull request Sep 22, 2017

DHT Query Performance #88

Closed

whyrusleeping added the status/ready Ready to be worked label Oct 17, 2017

whyrusleeping closed this Oct 17, 2017

whyrusleeping removed the status/ready Ready to be worked label Oct 17, 2017

whyrusleeping reopened this Oct 17, 2017

whyrusleeping added the status/in-progress In progress label Oct 17, 2017

ghost removed the status/in-progress In progress label Oct 17, 2017

ghost assigned whyrusleeping Oct 17, 2017

ghost added the status/in-progress In progress label Oct 17, 2017

laser and others added 11 commits September 6, 2018 12:10

update autobatch to 0.2.9

93fe9f7

upgrade go-datastore to 2.2.0

5d7748f

add delay

5df8091

use autobatch from go-datastore

c40fd0e

increase timeout threshhold to accommodate new PutValue perf

79de04c

initialize stream with DHT protocols as per new API post-rebase

dda877c

replace delayed datastore with mocknet + latency

cb5284f

remove unused gx deps

314c5db

Briefly comment singleMes

7578cd8

fix broken package.json

fc3cb0f

rebase artifact...

fix broken test

4737c8a

vyzo force-pushed the feat/request-pipeline branch from e174e62 to 4737c8a Compare September 6, 2018 09:37

ghost added the topic/filecoin Topic filecoin label Oct 26, 2018

anacrolix self-assigned this Jan 21, 2019

anacrolix mentioned this pull request Feb 20, 2019

Stream pooling #271

Closed

anacrolix mentioned this pull request Mar 26, 2019

What metrics to export? #304

Open

bigs removed their assignment Jan 29, 2020

Stebalien mentioned this pull request Feb 22, 2020

Occasional blocking when using Provide() #453

Closed

Stebalien closed this May 29, 2020

DHT Request pipelining #92

DHT Request pipelining #92

Conversation

vyzo commented Sep 17, 2017

vyzo commented Sep 17, 2017

vyzo commented Sep 17, 2017

vyzo commented Sep 20, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

whyrusleeping commented Sep 21, 2017

vyzo commented Sep 22, 2017 • edited Loading

vyzo commented Sep 22, 2017

whyrusleeping commented Oct 14, 2017

vyzo commented Oct 14, 2017

whyrusleeping commented Oct 17, 2017

vyzo commented Sep 6, 2018

bigs commented Sep 6, 2018

vyzo commented Sep 7, 2018

Stebalien commented Sep 12, 2018

raulk commented Feb 11, 2019

anacrolix commented Feb 11, 2019

anacrolix commented Feb 13, 2019

whyrusleeping commented Feb 13, 2019

Stebalien commented Feb 13, 2019

anacrolix commented Feb 20, 2019

Stebalien commented May 29, 2020

vyzo commented Sep 20, 2017 •

edited

Loading

vyzo commented Sep 22, 2017 •

edited

Loading