Hare inbound gossip message processing delays

[lrettig]

Description

Nodes are taking as long as a minute to receive inbound Hare gossip messages and report them as valid (after which they're gossiped on to other peers).

I can't tell exactly what's going on under the hood without full debug logs. It could be an issue with the Hare broker priority queue, message validation, or something else. I suspect it's happening during the Hare broker eventLoop.

Environment

Please complete the following information:

• OS: Linux
• Node Version: v0.1.41

Additional Resources

from https://testnet-kibana.spacemesh.io/goto/29beacaf0fe3b5c3757deed8d6f8788a

[lrettig]

Dug a bit deeper using debug logs:

full data:
hare backlog (1).csv
hare backlog.csv
from https://testnet-kibana.spacemesh.io/goto/91ecf641e57a09491279144a2f4d0d67

The hare broker is getting stuck somewhere in here:

go-spacemesh/hare/broker.go

Lines 232 to 269 in 3645848

	msgLogger.With().Debug("broker received hare message", log.Int("queue_length", len(b.inbox)))
	// TODO: fix metrics
	// metrics.MessageTypeCounter.With("type_id", hareMsg.InnerMsg.Type.String(), "layer", strconv.FormatUint(uint64(msgInstID), 10), "reporter", "brokerHandler").Add(1)
	msgInstID := hareMsg.InnerMsg.InstanceID
	msgLogger = msgLogger.WithFields(log.FieldNamed("msg_layer_id", types.LayerID(msgInstID)))
	isEarly := false
	if err := b.validate(messageCtx, hareMsg); err != nil {
	if err != errEarlyMsg {
	// not early, validation failed
	msgLogger.With().Debug("broker received a message to a consensus process that is not registered",
	log.Err(err))
	continue
	}
	msgLogger.With().Debug("early message detected", log.Err(err))
	isEarly = true
	}
	// the msg is either early or has instance
	// create msg
	iMsg, err := newMsg(messageCtx, hareMsg, b.stateQuerier)
	if err != nil {
	msgLogger.With().Warning("message validation failed: could not construct msg", log.Err(err))
	continue
	}
	// validate msg
	if !b.eValidator.Validate(messageCtx, iMsg) {
	msgLogger.With().Warning("message validation failed: eligibility validator returned false",
	log.String("hare_msg", hareMsg.String()))
	continue
	}
	// validation passed, report
	msg.ReportValidation(ctx, protoName)
	msgLogger.With().Debug("broker reported hare message as valid", hareMsg)

It seems like it's either the eligibility validator or the newMsg call. Both of these rely on the Hare oracle, which does use a mutex. And there's one or two other parallel hare goroutines also using the Hare oracle from the main consensus process code in algorithm.go, including:

go-spacemesh/hare/algorithm.go

Lines 286 to 303 in 3645848

	// check participation and send message
	go func() {
	// check participation
	if proc.shouldParticipate(ctx) {
	// set pre-round InnerMsg and send
	builder, err := proc.initDefaultBuilder(proc.s)
	if err != nil {
	logger.With().Error("init default builder failed", log.Err(err))
	return
	}
	m := builder.SetType(pre).Sign(proc.signing).Build()
	proc.sendMessage(ctx, m)
	} else {
	logger.With().Info("should not participate",
	log.Int32("current_k", proc.k),
	types.LayerID(proc.instanceID))
	}
	}()

But I can't find any blocking calls that would cause it to get stuck for as long as 60 secs.

[dshulyak]

there is a graph traversal function that may do many reads from disk and it is executed while holding the exclusive lock in the oracle

go-spacemesh/activation/atxdb.go

Lines 248 to 274 in 100d5ce

	func (db *DB) CalcActiveSetSize(epoch types.EpochID, blocks map[types.BlockID]struct{}) (map[string]struct{}, error) {
	if epoch == 0 {
	return nil, errors.New("tried to retrieve active set for epoch 0")
	}
	firstLayerOfPrevEpoch := (epoch - 1).FirstLayer()
	countedAtxs := make(map[string]types.ATXID)
	penalties := make(map[string]struct{})
	traversalFunc := db.createTraversalActiveSetCounterFunc(countedAtxs, penalties, db.LayersPerEpoch, epoch)
	startTime := time.Now()
	if err := db.meshDb.ForBlockInView(blocks, firstLayerOfPrevEpoch, traversalFunc); err != nil {
	return nil, err
	}
	db.log.With().Info("done calculating active set size",
	log.Int("size", len(countedAtxs)),
	log.String("duration", time.Now().Sub(startTime).String()))
	result := make(map[string]struct{}, len(countedAtxs))
	for k := range countedAtxs {
	result[k] = struct{}{}
	}
	return result, nil
	}

. i don't understand why i can't find the log line "done calculating active set size" with timings in the elastic. the text of log has changed between 0.1.41 and current version, but i can't find either.

[lrettig]

@dshulyak you were right:

done calculating active set size | atxDb | 1m13.812238934s

Here it is in the live testnet logs: https://testnet-kibana.spacemesh.io/goto/48b95795d097bdd1cabca9d825b3ca93

[lrettig]

Each node only needs to calculate this once per epoch, but it takes a very long time (then it's cached). This explains why the issue only pops up sporadically.

As a quick workaround, we could trigger the calculation before it's needed, run it concurrently and cache it. But I think we need to understand why this is so slow (I/O, I suppose) and speed it up.

[lrettig]

Here's a workaround: 377e908

I'll PR this into develop as well but need to rework it, as testnet and develop have diverged.