les: implement request distributor, fix blocking issues #3660

zsfelfoldi · 2017-02-10T02:23:39Z

This PR implements a new, cleaner and more efficient LES request distribution mechanism that also avoids starvation issues by prioritizing requests that have been created earlier. Also, it fixes a minor issue in light.TxPool.

mention-bot · 2017-02-10T02:23:40Z

@zsfelfoldi, thanks for your PR! By analyzing the history of the files in this pull request, we identified @obscuren, @fjl and @bas-vk to be potential reviewers.

mchusovlianov · 2017-02-10T05:12:31Z

I've tested a bit this PR ( I just run ./build/bin/geth --light --testnet console and i try to dump eth object by typing eth ENTER):
1 issue:

2 issue:

zsfelfoldi · 2017-02-10T11:02:41Z

thanks for the bug report, I will fix it soon.

zsfelfoldi · 2017-02-10T12:16:16Z

fixed

mchusovlianov · 2017-02-10T12:47:04Z

It looks now it has deadlock:

zsfelfoldi · 2017-02-10T13:13:10Z

Not a deadlock, the server was disconnected. Did it happen because of your 'eth' command?

farazdagi · 2017-02-10T13:14:26Z

I can confirm the same, if you type 'eth, eth, .. , eth N' at some (not very high) N, everything blocks, and nothing happens, smells lots like deadlock
the same rollback is reported in mine console too:

zsfelfoldi · 2017-02-10T13:20:56Z

Does it say "Rolled back 2048 headers..." like on the picture above? That means server disconnection during syncing. Which is bad too if an 'eth' command causes that, but it is a different issue.

farazdagi · 2017-02-10T13:22:31Z

yep, it always (at least in my anecdotical evidence) happens in sequence: "eth" strings start to pile, and then "rolled back" message appears, and while I can input anything, no response from server ever comes
Additionally, when I had another console attached in a separate window, it also just locks, when "eth DOS" happens in the first window. I wanted to have that separate window, to see the peers (to investigate why server disconnect occurs).

zsfelfoldi · 2017-02-10T19:05:29Z

Please try it again... there is still some weird issue when resuming a cancelled syncing (after header rollback), I will debug that later, but the really nasty bug that caused blocking has been found.

farazdagi · 2017-02-10T19:15:05Z

Thank you! The issue seems to be resolved - at least I couldn't overwhelm console with "eth" calls. Rollbacks happen - yet sync resumes and full sync happens, eventually.

So, all in all - this nasty blocking bug has been resolved.

farazdagi · 2017-02-11T00:04:53Z

I've done more tests, unfortunately got the following panic:

zsfelfoldi · 2017-02-11T00:27:39Z

Thanks for catching it, fixed. Now I am carefully checking all my locks, callbacks and goroutines :)

zsfelfoldi · 2017-02-14T18:12:37Z

also fixed a bug that caused flow control errors and random peer disconnections.

farazdagi · 2017-02-15T23:58:09Z

While overall blocking is gone indeed, there's one minor issue with a delay, rather than a block.

I've done the following experiment:

wiped out chaindata (so that the test starts from trusted CHT, and needs to sync all the way from it)
send couple of transactions
- sometimes those transactions validate just fine, even if actual nonce is higher (in the last block), it might so happen that when tx is sent, chain state doesn't know about those higher nonces
- curiously enough, the first transaction proceeds fine (of course it never gets included into blockchain, as peers deny it)
- however, the second take much longer to complete (like minutes, instead of seconds)

I've tracked the problem to https://github.com/ethereum/go-ethereum/blob/master/light/txpool.go#L303:

func (pool *TxPool) eventLoop() {
	for ev := range pool.events.Chan() {
		switch ev.Data.(type) {
		case core.ChainHeadEvent:
			pool.mu.Lock()
			ctx, _ := context.WithTimeout(context.Background(), blockCheckTimeout)
			head := pool.chain.CurrentHeader()
			txc, _ := pool.setNewHead(ctx, head)
			m, r := txc.getLists()
			pool.relay.NewHead(pool.head, m, r)
			pool.homestead = pool.config.IsHomestead(head.Number)
			pool.signer = types.MakeSigner(pool.config, head.Number)
			pool.mu.Unlock()
                        // <<<<<< delay is solved if I add time.Sleep(0) or runtime.Gosched()
		}
	}
}

So, eventLoop acquires lock and preemption seems to get greatly delayed i.e. another routine was starving on txpool.Add() lock acquiring - hence the delay.

Once I added runtim.Gosched() to allow for manual preemption and context switching, no more delays occurred.

zsfelfoldi · 2017-02-20T12:48:58Z

@farazdagi thanks for reporting these issues, I've switched the status of the PR back to "in progress" until I address them.

zsfelfoldi · 2017-03-04T19:09:33Z

@farazdagi I have investigated the mentioned issues and found the following:

if you send a transaction before syncing up, the light transaction pool kills performance by downloading each block until it finds the sent transaction. It also wastes some CPU performance while syncing, even if no tx has been sent. This problem will be fixed by a subsequent PR.
serving data from the local db before syncing is started DOES work if everything is there, or at least I could not reproduce a scenario where it does not. The comments above the Retrieve funcion were outdated, db checking is done in the access functions found in light/odr_util.go.
the commit c57c54c you mentioned only affected the server mode and was rolled back since then, so it can not be related to these problems.

Hopefully the remaining performance and responsiveness issues will be fixed by the new (and actually simpler) light tx pool which will (again, hopefully) be included in the 1.6 release.

farazdagi · 2017-03-05T22:41:08Z

@zsfelfoldi thank you for providing more details. I've mentioned this on Gitter, copying it here:

in my tests #3660 still doesn't fix the blocking. I did the following: 1. reset chaindata 2. start node 3. in another window attach to that node 4. try to eth.getBalance() and eth.estimateGas() 5. blocking/lags occurs.

So, unfortunately, for us it this remaining performance and responsiveness issues were show stoppers (as on mobile LES is already understandably slower than that on desktop). What we did is simply excluded any updates that happened from c57c54c I literally cherry-picked every other commits, but ones related to LES, and we have non blocking and almost up to date Geth (everything is up to date, except for LES).

I am not sure how c57c54c is unrelated to the issue - I see no blocking before that commit, I see no blocking if I update everything else bug LES. It is possible that commit has been reverted, and then something else re-introduced the issue, I am not sure.

At the moment we have our hackish way to keep updated Geth and outdated LES 😞 - once I have more time, I will look further into issue, as the original issue I've reported (#3639) is definitely not fixed by this PR, so hopefully it gets addressed down the road.

fjl

We did an interactive review.

fjl · 2017-03-18T00:13:19Z

les/distributor.go

+	waitBefore(uint64) (time.Duration, float64)
+	canSendOrdered() bool
+	orderedSend(f func())
+}


As discussed, please remove the need for 'ordered sends' by updating flow control counters when the request is actually sent.

I realized that I'd really want to keep the ordered send because the order actually affects performance, the optimal thing to do is to keep the queue priority and always send the oldest requests first. I know this is a minor nuance but with the recent additions to the protocol there are cases where the order of reply messages counts too, so I believe in the long run this is the cleanest solution. So I made the ordered send a general thing and put it into the common package.

fjl · 2017-03-18T00:13:54Z

les/distributor.go

+		case retry := <-d.loopChn:
+			// the main loop distinguishes two kinds of signals:
+			// - "retry" is sent to re-check whether previously unsendable requests can now be sent to one of the peers
+			// - "next" is sent when there are more requests to be processed/sent


Please remove the retry mechanism.

fjl · 2017-03-18T00:14:38Z

les/distributor.go

+				r.queuePrev.queueNext = r
+			}
+		}
+	}


You might be able to remove this part if you use container/list.

fjl · 2017-03-18T00:17:41Z

les/distributor.go

+		getCost: getCost,
+		canSend: canSend,
+		request: request,
+	}


Please change callers to use &distReq{getCost: func(...) uint64 { ... }, ...} instead of calling newDistReq. Doing this will add "labels" to all the func literals.

fjl · 2017-03-18T00:18:43Z

les/distributor.go

+	}
+	if bestReq == nil {
+	} else {
+	}


You don't need this empty condition anymore ;)

fjl · 2017-03-18T00:19:18Z

les/distributor.go

+					if send != nil {
+						peer.orderedSend(send)
+					}
+					chn <- peer


req.sentChn <- peer close(req.sentChn)

No, I realized that remove sets sentChn to nil so there was actually a reason for this.

fjl · 2017-03-18T00:19:34Z

les/distributor.go

+				}
+				fmt.Println(" order", r.reqOrder, "prev", p)
+				r = r.queueNext
+			}


Please remove this select clause.

GitCop · 2017-03-18T17:39:00Z

Thank you for your contribution! Your commits seem to not adhere to the repository coding standards

Commit: 4f3a9eea6aff8d15aa7ce328af343e32c6bc653e
Commits must be prefixed with the package(s) they modify
Commit: 73f68d563c1fa1d0e01cedcebbe91726b2ace6de
Commits must be prefixed with the package(s) they modify
Commit: 04067f3fffb9a0ef4bf36604ec197be79cb8c337
Commits must be prefixed with the package(s) they modify
Commit: 9a82a89c338754e1b5bd0d3542ca9499ba473d7b
Commits must be prefixed with the package(s) they modify

Please check the contribution guidelines for more details.

This message was auto-generated by https://gitcop.com

zsfelfoldi · 2017-03-18T17:50:38Z

@fjl I did the requested changes (except two of them, see my comments).

fjl · 2017-03-22T01:34:03Z

common/execqueue.go

+// Stop stops the exec queue.
+func (q *ExecQueue) Stop() {
+	atomic.StoreInt32(&q.stop, 1)
+}


Please add this as an unexported utility in package les instead. We don't want to add new features to package common anymore.

fjl · 2017-03-22T19:40:54Z

light/lightchain.go

-	defer self.chainmu.Unlock()
+	defer func() {
+		self.chainmu.Unlock()
+		time.Sleep(time.Millisecond * 10) // ugly hack; do not hog chain lock in case syncing is CPU-limited by validation


This is indeed ugly and we should remove it. Can you explain why this helps with the lock?

fjl · 2017-03-22T19:41:51Z

les/distributor.go

+					}
+					go func() {
+						time.Sleep(wait)
+						d.loopChn <- struct{}{}


I have a better idea for this, will submit after the merge.

obscuren added the in progress label Feb 10, 2017

zsfelfoldi added this to the 1.5.9 milestone Feb 10, 2017

This was referenced Feb 10, 2017

les: unresponsive server up until sync is done #3639

Closed

Find solution to blocking eth calls (during sync) status-im/status-go#102

Closed

zsfelfoldi force-pushed the sync-blocking-fix branch from c421755 to 16a3244 Compare February 10, 2017 12:14

farazdagi mentioned this pull request Feb 11, 2017

Fix LES blocking on sync status-im/status-go#107

Closed

zsfelfoldi force-pushed the sync-blocking-fix branch from aee030f to d61ed3f Compare February 13, 2017 02:29

zsfelfoldi added review and removed in progress labels Feb 13, 2017

zsfelfoldi assigned fjl Feb 13, 2017

karalabe modified the milestones: 1.5.10, 1.5.9 Feb 13, 2017

zsfelfoldi added the in progress label Feb 14, 2017

zsfelfoldi force-pushed the sync-blocking-fix branch from 57e550e to 53e7cae Compare February 14, 2017 17:48

zsfelfoldi removed the in progress label Feb 14, 2017

zsfelfoldi added in progress and removed review labels Feb 20, 2017

zsfelfoldi force-pushed the sync-blocking-fix branch from 53e7cae to f93567b Compare March 3, 2017 17:41

zsfelfoldi unassigned fjl Mar 3, 2017

zsfelfoldi force-pushed the sync-blocking-fix branch from f93567b to 3d221cc Compare March 4, 2017 18:54

zsfelfoldi added review and removed in progress labels Mar 4, 2017

zsfelfoldi added in progress and removed review labels Mar 6, 2017

zsfelfoldi mentioned this pull request Mar 9, 2017

eth.getBlock('latest') doesn’t return anything when geth --light is synchronizing #3767

Closed

zsfelfoldi force-pushed the sync-blocking-fix branch from 5b8fd05 to ee21f96 Compare March 11, 2017 22:34

zsfelfoldi added review and removed in progress labels Mar 11, 2017

farazdagi mentioned this pull request Mar 13, 2017

LES: update to the latest version status-im/status-go#121

Closed

zsfelfoldi force-pushed the sync-blocking-fix branch from ee21f96 to b5afe61 Compare March 17, 2017 01:00

fjl requested changes Mar 18, 2017

View reviewed changes

fjl reviewed Mar 22, 2017

View reviewed changes

zsfelfoldi force-pushed the sync-blocking-fix branch from 9a82a89 to e802e27 Compare March 22, 2017 14:34

zsfelfoldi added 2 commits March 22, 2017 15:38

core: moved header validation before chain mutex lock

b97c2c5

les: implement request distributor, fix blocking issues

9d363f3

zsfelfoldi force-pushed the sync-blocking-fix branch from e802e27 to 9d363f3 Compare March 22, 2017 14:39

fjl reviewed Mar 22, 2017

View reviewed changes

fjl approved these changes Mar 22, 2017

View reviewed changes

fjl merged commit 525116d into ethereum:master Mar 22, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

les: implement request distributor, fix blocking issues #3660

les: implement request distributor, fix blocking issues #3660

zsfelfoldi commented Feb 10, 2017

mention-bot commented Feb 10, 2017

mchusovlianov commented Feb 10, 2017 •

edited

Loading

zsfelfoldi commented Feb 10, 2017

zsfelfoldi commented Feb 10, 2017

mchusovlianov commented Feb 10, 2017

zsfelfoldi commented Feb 10, 2017

farazdagi commented Feb 10, 2017 •

edited

Loading

zsfelfoldi commented Feb 10, 2017

farazdagi commented Feb 10, 2017 •

edited

Loading

zsfelfoldi commented Feb 10, 2017

farazdagi commented Feb 10, 2017

farazdagi commented Feb 11, 2017

zsfelfoldi commented Feb 11, 2017

zsfelfoldi commented Feb 14, 2017

farazdagi commented Feb 15, 2017

zsfelfoldi commented Feb 20, 2017

zsfelfoldi commented Mar 4, 2017

farazdagi commented Mar 5, 2017

fjl left a comment

fjl Mar 18, 2017

zsfelfoldi Mar 18, 2017

fjl Mar 18, 2017

fjl Mar 18, 2017

fjl Mar 18, 2017

fjl Mar 18, 2017

fjl Mar 18, 2017

zsfelfoldi Mar 18, 2017

fjl Mar 18, 2017

GitCop commented Mar 18, 2017

zsfelfoldi commented Mar 18, 2017

fjl Mar 22, 2017

zsfelfoldi Mar 22, 2017

fjl Mar 22, 2017 •

edited

Loading

fjl Mar 22, 2017

les: implement request distributor, fix blocking issues #3660

les: implement request distributor, fix blocking issues #3660

Conversation

zsfelfoldi commented Feb 10, 2017

mention-bot commented Feb 10, 2017

mchusovlianov commented Feb 10, 2017 • edited Loading

zsfelfoldi commented Feb 10, 2017

zsfelfoldi commented Feb 10, 2017

mchusovlianov commented Feb 10, 2017

zsfelfoldi commented Feb 10, 2017

farazdagi commented Feb 10, 2017 • edited Loading

zsfelfoldi commented Feb 10, 2017

farazdagi commented Feb 10, 2017 • edited Loading

zsfelfoldi commented Feb 10, 2017

farazdagi commented Feb 10, 2017

farazdagi commented Feb 11, 2017

zsfelfoldi commented Feb 11, 2017

zsfelfoldi commented Feb 14, 2017

farazdagi commented Feb 15, 2017

zsfelfoldi commented Feb 20, 2017

zsfelfoldi commented Mar 4, 2017

farazdagi commented Mar 5, 2017

fjl left a 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

GitCop commented Mar 18, 2017

zsfelfoldi commented Mar 18, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fjl Mar 22, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mchusovlianov commented Feb 10, 2017 •

edited

Loading

farazdagi commented Feb 10, 2017 •

edited

Loading

farazdagi commented Feb 10, 2017 •

edited

Loading

fjl Mar 22, 2017 •

edited

Loading