miner: refactor code for multiple smesher and better observability (#…

…5130)

related: #5113 

it drops RefBallot function, and will allow to drop that index in a followup

related: #5106 

it eliminates repetitive disk reads and makes potentially expensive calls more transparent. added latency of execution to the logs

related: #5087 

refactoring to draw a line between per-smesher data that needs to be loaded once per epoch, and calls to external components. tortoise/mesh hash are reusable for every smesher, get txs is not reusable. it makes adding support for multiple smeshers significantly simpler

common/types/proposal.go

@@ -85,6 +85,12 @@ func (p *Proposal) Initialize() error {
 	return nil
 }
 
+func (p *Proposal) MustInitialize() {
+	if err := p.Initialize(); err != nil {
+		panic(err)
+	}
+}
+
 // SignedBytes returns the serialization of the InnerProposal.
 func (p *Proposal) SignedBytes() []byte {
 	data, err := codec.Encode(&BallotMetadata{
@@ -120,13 +126,8 @@ func (p *Proposal) SetID(pid ProposalID) {
 // MarshalLogObject implements logging interface.
 func (p *Proposal) MarshalLogObject(encoder log.ObjectEncoder) error {
 	encoder.AddString("proposal_id", p.ID().String())
-	encoder.AddArray("transactions", log.ArrayMarshalerFunc(func(encoder log.ArrayEncoder) error {
-		for _, id := range p.TxIDs {
-			encoder.AppendString(id.String())
-		}
-		return nil
-	}))
-	encoder.AddString("mesh_hash", p.MeshHash.String())
+	encoder.AddInt("transactions", len(p.TxIDs))
+	encoder.AddString("mesh_hash", p.MeshHash.ShortString())
 	p.Ballot.MarshalLogObject(encoder)
 	return nil
 }

miner/metrics.go

@@ -0,0 +1,46 @@
+package miner
+
+import (
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+
+	"github.com/spacemeshos/go-spacemesh/log"
+	"github.com/spacemeshos/go-spacemesh/metrics"
+)
+
+var proposalBuild = metrics.NewHistogramWithBuckets(
+	"proposal_build_seconds",
+	"miner",
+	"duration to build a proposal in seconds",
+	[]string{},
+	prometheus.ExponentialBuckets(0.1, 2, 10),
+).WithLabelValues()
+
+type latencyTracker struct {
+	start    time.Time
+	data     time.Time
+	tortoise time.Time
+	txs      time.Time
+	hash     time.Time
+	publish  time.Time
+}
+
+func (lt *latencyTracker) total() time.Duration {
+	return lt.publish.Sub(lt.start)
+}
+
+func (lt *latencyTracker) MarshalLogObject(encoder log.ObjectEncoder) error {
+	encoder.AddDuration("data", lt.data.Sub(lt.start))
+	encoder.AddDuration("tortoise", lt.tortoise.Sub(lt.data))
+	encoder.AddDuration("txs", lt.txs.Sub(lt.tortoise))
+	encoder.AddDuration("hash", lt.hash.Sub(lt.txs))
+	encoder.AddDuration("publish", lt.publish.Sub(lt.hash))
+	total := lt.total()
+	encoder.AddDuration("total", total)
+	// arbitrary threshold that we want to highlight as a problem
+	if total > 10*time.Second {
+		encoder.AddBool("LATE PROPOSAL", true)
+	}
+	return nil
+}