private StateSyncBatch PrepareRequest()
{
StateSyncBatch request = _nodeDataFeed.PrepareRequest(MaxRequestSize);
if (_logger.IsTrace)
{
_logger.Trace($"Pending requests {_pendingRequests}");
}
return(request);
}
private async Task ExecuteRequest(CancellationToken token, StateSyncBatch batch)
{
SyncPeerAllocation nodeSyncAllocation = _syncPeerPool.Borrow(BorrowOptions.DoNotReplace, "node sync");
try
{
ISyncPeer peer = nodeSyncAllocation?.Current?.SyncPeer;
batch.AssignedPeer = nodeSyncAllocation;
if (peer != null)
{
var hashes = batch.RequestedNodes.Select(r => r.Hash).ToArray();
Task <byte[][]> getNodeDataTask = peer.GetNodeData(hashes, token);
await getNodeDataTask.ContinueWith(
t =>
{
if (t.IsCompletedSuccessfully)
{
batch.Responses = getNodeDataTask.Result;
}
}
);
}
(NodeDataHandlerResult Result, int NodesConsumed)result = (NodeDataHandlerResult.InvalidFormat, 0);
try
{
result = _nodeDataFeed.HandleResponse(batch);
if (result.Result == NodeDataHandlerResult.BadQuality)
{
_syncPeerPool.ReportBadPeer(batch.AssignedPeer);
}
}
catch (Exception e)
{
if (_logger.IsError)
{
_logger.Error($"Error when handling response", e);
}
}
Interlocked.Add(ref _consumedNodesCount, result.NodesConsumed);
if (result.NodesConsumed == 0 && peer != null)
{
_syncPeerPool.ReportNoSyncProgress(nodeSyncAllocation);
}
}
finally
{
if (nodeSyncAllocation != null)
{
// _logger.Warn($"Free {nodeSyncAllocation?.Current}");
_syncPeerPool.Free(nodeSyncAllocation);
}
}
}
public StateSyncBatch PrepareRequest(int length)
{
if (_rootNode == Keccak.EmptyTreeHash)
{
return(_emptyBatch);
}
StateSyncBatch batch = new StateSyncBatch();
if (_logger.IsTrace)
{
_logger.Trace($"Preparing a request of length {length} from ({Stream0.Count}|{Stream1.Count}|{Stream2.Count}) nodes");
}
List <StateSyncItem> requestHashes = new List <StateSyncItem>();
for (int i = 0; i < length; i++)
{
if (TryTake(out StateSyncItem requestItem))
{
if (_logger.IsTrace)
{
_logger.Trace($"Requesting {requestItem.Hash}");
}
requestHashes.Add(requestItem);
}
else
{
break;
}
}
batch.RequestedNodes = requestHashes.ToArray();
StateSyncBatch result = batch.RequestedNodes == null ? _emptyBatch : batch;
Interlocked.Add(ref _requestedNodesCount, result.RequestedNodes.Length);
if (_logger.IsTrace)
{
_logger.Trace($"After preparing a request of {length} from ({Stream0.Count}|{Stream1.Count}|{Stream2.Count}) nodes");
}
if (result.RequestedNodes.Length > 0)
{
_pendingRequests.TryAdd(result, _nullObject);
}
return(result);
}
private async Task KeepSyncing(CancellationToken token)
{
do
{
if (token.IsCancellationRequested)
{
return;
}
await UpdateParallelism();
if (!await _semaphore.WaitAsync(1000, token))
{
continue;
}
StateSyncBatch request = PrepareRequest();
if (request.RequestedNodes.Length != 0)
{
Interlocked.Increment(ref _pendingRequests);
if (_logger.IsTrace)
{
_logger.Trace($"Creating new request with {request.RequestedNodes.Length} nodes");
}
Task task = ExecuteRequest(token, request);
#pragma warning disable 4014
task.ContinueWith(t =>
#pragma warning restore 4014
{
Interlocked.Decrement(ref _pendingRequests);
_semaphore.Release();
});
}
else
{
await Task.Delay(50);
_semaphore.Release();
if (_logger.IsDebug)
{
_logger.Debug($"DIAG: 0 batches created with {_pendingRequests} pending requests, {_nodeDataFeed.TotalNodesPending} pending nodes");
}
}
} while (_pendingRequests != 0);
if (_logger.IsInfo)
{
_logger.Info($"Finished with {_pendingRequests} pending requests and {_lastUsefulPeerCount} useful peers.");
}
}
public (NodeDataHandlerResult Result, int NodesConsumed) HandleResponse(StateSyncBatch batch)
{
int requestLength = batch.RequestedNodes?.Length ?? 0;
int responseLength = batch.Responses?.Length ?? 0;
void AddAgainAllItems()
{
for (int i = 0; i < requestLength; i++)
{
AddNode(batch.RequestedNodes[i], null, "missing", true);
}
}
try
{
lock (_handleWatch)
{
_handleWatch.Restart();
bool requestWasMade = batch.AssignedPeer?.Current != null;
NodeDataHandlerResult result;
if (!requestWasMade)
{
AddAgainAllItems();
if (_logger.IsTrace)
{
_logger.Trace($"Batch was not assigned to any peer.");
}
Interlocked.Increment(ref _notAssignedCount);
result = NodeDataHandlerResult.NotAssigned;
return(result, 0);
}
bool isMissingRequestData = batch.RequestedNodes == null;
bool isMissingResponseData = batch.Responses == null;
bool hasValidFormat = !isMissingRequestData && !isMissingResponseData;
if (!hasValidFormat)
{
AddAgainAllItems();
if (_logger.IsDebug)
{
_logger.Debug($"Batch response had invalid format");
}
Interlocked.Increment(ref _invalidFormatCount);
result = NodeDataHandlerResult.InvalidFormat;
return(result, 0);
}
if (_logger.IsTrace)
{
_logger.Trace($"Received node data - {responseLength} items in response to {requestLength}");
}
int nonEmptyResponses = 0;
int invalidNodes = 0;
for (int i = 0; i < batch.RequestedNodes.Length; i++)
{
StateSyncItem currentStateSyncItem = batch.RequestedNodes[i];
/* if the peer has limit on number of requests in a batch then the response will possibly be
* shorter than the request */
if (batch.Responses.Length < i + 1)
{
AddNode(currentStateSyncItem, null, "missing", true);
continue;
}
/* if the peer does not have details of this particular node */
byte[] currentResponseItem = batch.Responses[i];
if (currentResponseItem == null)
{
AddNode(batch.RequestedNodes[i], null, "missing", true);
continue;
}
/* node sent data that is not consistent with its hash - it happens surprisingly often */
if (Keccak.Compute(currentResponseItem) != currentStateSyncItem.Hash)
{
if (_logger.IsDebug)
{
_logger.Debug($"Peer sent invalid data (batch {requestLength}->{responseLength}) of length {batch.Responses[i]?.Length} of type {batch.RequestedNodes[i].NodeDataType} at level {batch.RequestedNodes[i].Level} of type {batch.RequestedNodes[i].NodeDataType} Keccak({batch.Responses[i].ToHexString()}) != {batch.RequestedNodes[i].Hash}");
}
invalidNodes++;
continue;
}
nonEmptyResponses++;
NodeDataType nodeDataType = currentStateSyncItem.NodeDataType;
if (nodeDataType == NodeDataType.Code)
{
SaveNode(currentStateSyncItem, currentResponseItem);
continue;
}
TrieNode trieNode = new TrieNode(NodeType.Unknown, new Rlp(currentResponseItem));
trieNode.ResolveNode(null);
switch (trieNode.NodeType)
{
case NodeType.Unknown:
invalidNodes++;
if (_logger.IsError)
{
_logger.Error($"Node {currentStateSyncItem.Hash} resolved to {nameof(NodeType.Unknown)}");
}
break;
case NodeType.Branch:
trieNode.BuildLookupTable();
DependentItem dependentBranch = new DependentItem(currentStateSyncItem, currentResponseItem, 0);
HashSet <Keccak> alreadyProcessedChildHashes = new HashSet <Keccak>();
for (int childIndex = 0; childIndex < 16; childIndex++)
{
Keccak child = trieNode.GetChildHash(childIndex);
if (alreadyProcessedChildHashes.Contains(child))
{
continue;
}
alreadyProcessedChildHashes.Add(child);
if (child != null)
{
AddNodeResult addChildResult = AddNode(new StateSyncItem(child, nodeDataType, currentStateSyncItem.Level + 1, CalculatePriority(currentStateSyncItem)), dependentBranch, "branch child");
if (addChildResult != AddNodeResult.AlreadySaved)
{
dependentBranch.Counter++;
}
}
}
if (dependentBranch.Counter == 0)
{
SaveNode(currentStateSyncItem, currentResponseItem);
}
break;
case NodeType.Extension:
Keccak next = trieNode[0].Keccak;
if (next != null)
{
DependentItem dependentItem = new DependentItem(currentStateSyncItem, currentResponseItem, 1);
AddNodeResult addResult = AddNode(new StateSyncItem(next, nodeDataType, currentStateSyncItem.Level + 1, currentStateSyncItem.Priority), dependentItem, "extension child");
if (addResult == AddNodeResult.AlreadySaved)
{
SaveNode(currentStateSyncItem, currentResponseItem);
}
}
else
{
/* this happens when we have a short RLP format of the node
* that would not be stored as Keccak but full RLP*/
SaveNode(currentStateSyncItem, currentResponseItem);
}
break;
case NodeType.Leaf:
if (nodeDataType == NodeDataType.State)
{
DependentItem dependentItem = new DependentItem(currentStateSyncItem, currentResponseItem, 0, true);
Account account = _accountDecoder.Decode(new Rlp.DecoderContext(trieNode.Value));
if (account.CodeHash != Keccak.OfAnEmptyString)
{
// prepare a branch without the code DB
// this only protects against being same as storage root?
if (account.CodeHash == account.StorageRoot)
{
lock (_codesSameAsNodes)
{
_codesSameAsNodes.Add(account.CodeHash);
}
}
else
{
AddNodeResult addCodeResult = AddNode(new StateSyncItem(account.CodeHash, NodeDataType.Code, 0, 0), dependentItem, "code");
if (addCodeResult != AddNodeResult.AlreadySaved)
{
dependentItem.Counter++;
}
}
}
if (account.StorageRoot != Keccak.EmptyTreeHash)
{
AddNodeResult addStorageNodeResult = AddNode(new StateSyncItem(account.StorageRoot, NodeDataType.Storage, 0, 0), dependentItem, "storage");
if (addStorageNodeResult != AddNodeResult.AlreadySaved)
{
dependentItem.Counter++;
}
}
if (dependentItem.Counter == 0)
{
Interlocked.Increment(ref _savedAccounts);
SaveNode(currentStateSyncItem, currentResponseItem);
}
}
else
{
SaveNode(currentStateSyncItem, currentResponseItem);
}
break;
default:
if (_logger.IsError)
{
_logger.Error($"Unknown value {currentStateSyncItem.NodeDataType} of {nameof(NodeDataType)} at {currentStateSyncItem.Hash}");
}
invalidNodes++;
continue;
}
}
lock (_stateDbLock)
{
Rlp rlp = Rlp.Encode(
Rlp.Encode(_consumedNodesCount),
Rlp.Encode(_savedStorageCount),
Rlp.Encode(_savedStateCount),
Rlp.Encode(_savedNodesCount),
Rlp.Encode(_savedAccounts),
Rlp.Encode(_savedCode),
Rlp.Encode(_requestedNodesCount),
Rlp.Encode(_dbChecks),
Rlp.Encode(_stateWasThere),
Rlp.Encode(_stateWasNotThere),
Rlp.Encode(_dataSize));
lock (_codeDbLock)
{
_codeDb[_fastSyncProgressKey.Bytes] = rlp.Bytes;
_codeDb.Commit();
_stateDb.Commit();
}
}
Interlocked.Add(ref _consumedNodesCount, nonEmptyResponses);
if (_logger.IsTrace)
{
_logger.Trace($"After handling response (non-empty responses {nonEmptyResponses}) of {batch.RequestedNodes.Length} from ({Stream0.Count}|{Stream1.Count}|{Stream2.Count}) nodes");
}
/* magic formula is ratio of our desired batch size - 1024 to Geth max batch size 384 times some missing nodes ratio */
bool isEmptish = (decimal)nonEmptyResponses / requestLength < 384m / 1024m * 0.75m;
if (isEmptish)
{
Interlocked.Increment(ref _emptishCount);
}
/* here we are very forgiving for Geth nodes that send bad data fast */
bool isBadQuality = nonEmptyResponses > 64 && (decimal)invalidNodes / requestLength > 0.50m;
if (isBadQuality)
{
Interlocked.Increment(ref _badQualityCount);
}
bool isEmpty = nonEmptyResponses == 0 && !isBadQuality;
if (isEmpty)
{
if (_logger.IsWarn)
{
_logger.Warn($"Peer sent no data in response to a request of length {batch.RequestedNodes.Length}");
}
result = NodeDataHandlerResult.NoData;
return(result, 0);
}
if (!isEmptish && !isBadQuality)
{
Interlocked.Increment(ref _okCount);
}
result = isEmptish
? NodeDataHandlerResult.Emptish
: isBadQuality
? NodeDataHandlerResult.BadQuality
: NodeDataHandlerResult.OK;
if (DateTime.UtcNow - _lastReportTime > TimeSpan.FromSeconds(1))
{
decimal requestedNodesPerSecond = 1000m * (_requestedNodesCount - _lastRequestedNodesCount) / (decimal)(DateTime.UtcNow - _lastReportTime).TotalMilliseconds;
decimal savedNodesPerSecond = 1000m * (_savedNodesCount - _lastSavedNodesCount) / (decimal)(DateTime.UtcNow - _lastReportTime).TotalMilliseconds;
_lastSavedNodesCount = _savedNodesCount;
_lastRequestedNodesCount = _requestedNodesCount;
_lastReportTime = DateTime.UtcNow;
if (_logger.IsInfo)
{
_logger.Info($"SNPS: {savedNodesPerSecond,6:F0} | RNPS: {requestedNodesPerSecond,6:F0} | Saved nodes {_savedNodesCount} / requested {_requestedNodesCount} ({(decimal) _savedNodesCount / _requestedNodesCount:P2}), saved accounts {_savedAccounts}, size: {(decimal)_dataSize / 1000 / 1000:F2}MB, enqueued nodes {Stream0.Count:D5}|{Stream1.Count:D5}|{Stream2.Count:D5}");
}
if (_logger.IsInfo)
{
_logger.Info($"AVTIH: {_averageTimeInHandler:F2}ms | P: {_pendingRequests.Count} | Request results - OK: {(decimal) _okCount / TotalRequestsCount:p2}, Emptish: {(decimal) _emptishCount / TotalRequestsCount:p2}, BadQuality: {(decimal) _badQualityCount / TotalRequestsCount:p2}, InvalidFormat: {(decimal) _invalidFormatCount / TotalRequestsCount:p2}, NotAssigned {(decimal) _notAssignedCount / TotalRequestsCount:p2}");
}
if (_logger.IsTrace)
{
_logger.Trace($"Requested {_requestedNodesCount}, consumed {_consumedNodesCount}, missed {_requestedNodesCount - _consumedNodesCount}, {_savedCode} contracts, {_savedStateCount - _savedAccounts} states, {_savedStorageCount} storage, DB checks {_stateWasThere}/{_stateWasNotThere + _stateWasThere} cached({_checkWasCached}+{_checkWasInDependencies})");
}
if (_logger.IsTrace)
{
_logger.Trace($"Consume : {(decimal) _consumedNodesCount / _requestedNodesCount:p2}, Save : {(decimal) _savedNodesCount / _requestedNodesCount:p2}, DB Reads : {(decimal) _dbChecks / _requestedNodesCount:p2}");
}
}
long total = _handleWatch.ElapsedMilliseconds + _networkWatch.ElapsedMilliseconds;
if (total != 0)
{
// calculate averages
if (_logger.IsTrace)
{
_logger.Trace($"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal) _networkWatch.ElapsedMilliseconds / total:P0}) - Handle {_handleWatch.ElapsedMilliseconds}ms ({(decimal) _handleWatch.ElapsedMilliseconds / total:P0})");
}
}
_averageTimeInHandler = (_averageTimeInHandler * (ProcessedRequestsCount - 1) + _handleWatch.ElapsedMilliseconds) / ProcessedRequestsCount;
return(result, nonEmptyResponses);
}
}
finally
{
_handleWatch.Stop();
if (!_pendingRequests.TryRemove(batch, out _))
{
_logger.Error("Cannot remove pending request");
}
}
}
