AncestorSearch algorithm is very inefficient

[xlc]

I have a small network setup with three validators. For some reason one of the validator end up been its own fork after about a day of running.

Most of the logs of the behind node is

2018-12-06 23:56:29 tokio-runtime-worker-0 TRACE sync  Requesting ancestry block #19692 from 56
2018-12-06 23:56:30  DEBUG tokio_reactor  loop process - 1 events, 0.000s
2018-12-06 23:56:30 tokio-runtime-worker-1 TRACE sync  BlockRequest 507 from 56: from Number(23741) to None max Some(1)
2018-12-06 23:56:30 tokio-runtime-worker-1 TRACE sync  Sending BlockResponse with 0 blocks
2018-12-06 23:56:30  DEBUG tokio_reactor  loop process - 1 events, 0.000s
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  BlockResponse 507 from 56 with 1 blocks (19692)
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  Got ancestry block #19692 (0x9baa…b0ef) from peer 56
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  Ancestry block mismatch for peer 56: theirs: 0x9baa…b0ef (19692), ours: Some(0xb1b916aec176f1765c66a07fbc207ba0371ed85a5d73f5e2c626de47c1fc518a)
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  Requesting ancestry block #19691 from 56
2018-12-06 23:56:30  DEBUG tokio_reactor  loop process - 1 events, 0.000s
2018-12-06 23:56:30 tokio-runtime-worker-1 TRACE sync  BlockRequest 508 from 56: from Number(23740) to None max Some(1)
2018-12-06 23:56:30 tokio-runtime-worker-1 TRACE sync  Sending BlockResponse with 0 blocks
2018-12-06 23:56:30  DEBUG tokio_reactor  loop process - 1 events, 0.000s
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  BlockResponse 508 from 56 with 1 blocks (19691)
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  Got ancestry block #19691 (0x3534…ff24) from peer 56
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  Ancestry block mismatch for peer 56: theirs: 0x3534…ff24 (19691), ours: Some(0x60d0ec86be645a25ced4301a20e5462c157a4839f5b84d29968f98f84bdc3724)
2018-12-06 23:56:30 tokio-runtime-worker-0 TRACE sync  Requesting ancestry block #19690 from 56
2018-12-06 23:56:31  DEBUG tokio_reactor  loop process - 1 events, 0.000s
2018-12-06 23:56:31 tokio-runtime-worker-1 TRACE sync  BlockRequest 509 from 56: from Number(23739) to None max Some(1)
2018-12-06 23:56:31 tokio-runtime-worker-1 TRACE sync  Sending BlockResponse with 0 blocks
2018-12-06 23:56:31 tokio-runtime-worker-1 DEBUG sync  Propagating extrinsics
2018-12-06 23:56:31 tokio-runtime-worker-0 INFO substrate  Syncing, target=#24281 (1 peers), best: #20199 (0x5a72…31b8)
2018-12-06 23:56:31  DEBUG tokio_reactor  loop process - 1 events, 0.000s
2018-12-06 23:56:31 tokio-runtime-worker-1 TRACE sync  BlockResponse 509 from 56 with 1 blocks (19690)
2018-12-06 23:56:31 tokio-runtime-worker-1 TRACE sync  Got ancestry block #19690 (0xd842…368f) from peer 56
2018-12-06 23:56:31 tokio-runtime-worker-1 TRACE sync  Ancestry block mismatch for peer 56: theirs: 0xd842…368f (19690), ours: Some(0x4815f6f6d1be14f7ff210f93070f9eebe3b72032991a2ea4db8b4e34b7c104a7)

Currently if a mismatched block found for n, it request block n-1 and until found a common ancestor or mismatched genesis.

substrate/core/network/src/sync.rs

Lines 224 to 226 in 0e85269

	trace!(target:"sync", "Ancestry block mismatch for peer {}: theirs: {} ({}), ours: {:?}", who, block.hash, n, our_best);
	let n = n - As::sa(1);
	peer.state = PeerSyncState::AncestorSearch(n);

This is very inefficient that it takes O(n) time to identify the most recent common ancestor. A binary search can make it O(log n). Because heuristically most recent common ancestor block is usually few blocks behind, it can do an exponential backoff style algorithm to find common ancestor. e.g. n - 1, n - 2, n - 4...