Fix validator performance logs (#9828)

* Fix validator performance logs

* Add test

* Clean both phase 0 and altair calculations

* Add back total inclusion distance

Co-authored-by: terence tsao <terence@prysmaticlabs.com>

validator/client/metrics.go

@@ -389,36 +389,35 @@ func (v *validator) LogValidatorGainsAndLosses(ctx context.Context, slot types.S
 func (v *validator) UpdateLogAggregateStats(resp *ethpb.ValidatorPerformanceResponse, slot types.Slot) {
 	summary := &v.voteStats
 	currentEpoch := types.Epoch(slot / params.BeaconConfig().SlotsPerEpoch)
-	var included uint64
+	var attested, correctSource, correctTarget, correctHead, inactivityScore int
-	var correctSource, correctTarget, correctHead, inactivityScore int
 
 	for i := range resp.PublicKeys {
-		// In phase0, we consider attestations included if the inclusion slot is not max uint64.
-		// In altair, we consider attestations included if correctlyVotedTarget is true.
 		if slots.ToEpoch(slot) < params.BeaconConfig().AltairForkEpoch && i < len(resp.InclusionDistances) {
 			if uint64(resp.InclusionSlots[i]) != ^uint64(0) {
-				included++
-				summary.includedAttestedCount++
 				summary.totalDistance += resp.InclusionDistances[i]
 			}
-		} else if resp.CorrectlyVotedTarget[i] {
-			included++
-			summary.includedAttestedCount++
 		}
 
+		included := false
 		if i < len(resp.CorrectlyVotedSource) && resp.CorrectlyVotedSource[i] {
+			included = true
 			correctSource++
-			summary.correctSources++
+			summary.totalCorrectSource++
 		}
 		if i < len(resp.CorrectlyVotedTarget) && resp.CorrectlyVotedTarget[i] {
+			included = true
 			correctTarget++
-			summary.correctTargets++
+			summary.totalCorrectTarget++
 		}
 		if i < len(resp.CorrectlyVotedHead) && resp.CorrectlyVotedHead[i] {
+			included = true
 			correctHead++
-			summary.correctHeads++
+			summary.totalCorrectHead++
+		}
+		if included {
+			attested++
+			summary.totalAttestedCount++
 		}
-
 		// Altair metrics
 		if slots.ToEpoch(slot) > params.BeaconConfig().AltairForkEpoch && i < len(resp.InactivityScores) {
 			inactivityScore += int(resp.InactivityScores[i])
@@ -426,27 +425,22 @@ func (v *validator) UpdateLogAggregateStats(resp *ethpb.ValidatorPerformanceResp
 	}
 
 	// Return early if no attestation got included from previous epoch.
-	// This happens when validators joined half way through epoch and already passed its assigned slot.
+	// This happens when validators joined halfway through epoch and already passed its assigned slot.
-	if included == 0 {
+	if attested == 0 {
 		return
 	}
 
-	summary.totalAttestedCount += uint64(len(resp.CorrectlyVotedTarget))
-	summary.totalSources += included
-	summary.totalTargets += included
-	summary.totalHeads += included
-
 	epochSummaryFields := logrus.Fields{
 		"epoch":                   currentEpoch - 1,
-		"attestationInclusionPct": fmt.Sprintf("%.0f%%", (float64(included)/float64(len(resp.CorrectlyVotedTarget)))*100),
+		"attestationInclusionPct": fmt.Sprintf("%.0f%%", (float64(attested)/float64(len(resp.PublicKeys)))*100),
-		"correctlyVotedSourcePct": fmt.Sprintf("%.0f%%", (float64(correctSource)/float64(included))*100),
+		"correctlyVotedSourcePct": fmt.Sprintf("%.0f%%", (float64(correctSource)/float64(attested))*100),
-		"correctlyVotedTargetPct": fmt.Sprintf("%.0f%%", (float64(correctTarget)/float64(included))*100),
+		"correctlyVotedTargetPct": fmt.Sprintf("%.0f%%", (float64(correctTarget)/float64(attested))*100),
-		"correctlyVotedHeadPct":   fmt.Sprintf("%.0f%%", (float64(correctHead)/float64(included))*100),
+		"correctlyVotedHeadPct":   fmt.Sprintf("%.0f%%", (float64(correctHead)/float64(attested))*100),
 	}
 
 	// Altair summary fields.
-	if slots.ToEpoch(slot) > params.BeaconConfig().AltairForkEpoch && len(resp.CorrectlyVotedTarget) > 0 {
+	if slots.ToEpoch(slot) > params.BeaconConfig().AltairForkEpoch && attested > 0 {
-		epochSummaryFields["averageInactivityScore"] = fmt.Sprintf("%.0f", float64(inactivityScore)/float64(len(resp.CorrectlyVotedTarget)))
+		epochSummaryFields["averageInactivityScore"] = fmt.Sprintf("%.0f", float64(inactivityScore)/float64(len(resp.PublicKeys)))
 	}
 
 	log.WithFields(epochSummaryFields).Info("Previous epoch aggregated voting summary")
@@ -457,27 +451,25 @@ func (v *validator) UpdateLogAggregateStats(resp *ethpb.ValidatorPerformanceResp
 		totalPrevBal += v.prevBalance[i]
 	}
 
-	if totalStartBal == 0 ||
+	if totalStartBal == 0 || summary.totalAttestedCount == 0 {
-		summary.includedAttestedCount == 0 ||
-		summary.totalSources == 0 ||
-		summary.totalTargets == 0 ||
-		summary.totalHeads == 0 {
 		log.Error("Failed to print launch summary: one or more divisors is 0")
 		return
 	}
 
+	summary.totalRequestedCount += uint64(len(resp.PublicKeys))
+
 	launchSummaryFields := logrus.Fields{
 		"numberOfEpochs":           fmt.Sprintf("%d", currentEpoch-summary.startEpoch),
-		"attestationsInclusionPct": fmt.Sprintf("%.0f%%", (float64(summary.includedAttestedCount)/float64(summary.totalAttestedCount))*100),
+		"attestationsInclusionPct": fmt.Sprintf("%.0f%%", (float64(summary.totalAttestedCount)/float64(summary.totalRequestedCount))*100),
-		"correctlyVotedSourcePct":  fmt.Sprintf("%.0f%%", (float64(summary.correctSources)/float64(summary.totalSources))*100),
+		"correctlyVotedSourcePct":  fmt.Sprintf("%.0f%%", (float64(summary.totalCorrectSource)/float64(summary.totalAttestedCount))*100),
-		"correctlyVotedTargetPct":  fmt.Sprintf("%.0f%%", (float64(summary.correctTargets)/float64(summary.totalTargets))*100),
+		"correctlyVotedTargetPct":  fmt.Sprintf("%.0f%%", (float64(summary.totalCorrectTarget)/float64(summary.totalAttestedCount))*100),
-		"correctlyVotedHeadPct":    fmt.Sprintf("%.0f%%", (float64(summary.correctHeads)/float64(summary.totalHeads))*100),
+		"correctlyVotedHeadPct":    fmt.Sprintf("%.0f%%", (float64(summary.totalCorrectHead)/float64(summary.totalAttestedCount))*100),
 		"pctChangeCombinedBalance": fmt.Sprintf("%.5f%%", (float64(totalPrevBal)-float64(totalStartBal))/float64(totalStartBal)*100),
 	}
 
 	// Add phase0 specific fields
 	if slots.ToEpoch(slot) < params.BeaconConfig().AltairForkEpoch {
-		launchSummaryFields["averageInclusionDistance"] = fmt.Sprintf("%.2f slots", float64(summary.totalDistance)/float64(summary.includedAttestedCount))
+		launchSummaryFields["averageInclusionDistance"] = fmt.Sprintf("%.2f slots", float64(summary.totalDistance)/float64(summary.totalAttestedCount))
 	}
 
 	log.WithFields(launchSummaryFields).Info("Vote summary since launch")

validator/client/metrics_test.go

@@ -4,9 +4,11 @@ import (
 	"testing"
 
 	types "github.com/prysmaticlabs/eth2-types"
+	"github.com/prysmaticlabs/prysm/config/params"
 	"github.com/prysmaticlabs/prysm/encoding/bytesutil"
 	ethpb "github.com/prysmaticlabs/prysm/proto/prysm/v1alpha1"
 	"github.com/prysmaticlabs/prysm/testing/require"
+	"github.com/prysmaticlabs/prysm/time/slots"
 	logTest "github.com/sirupsen/logrus/hooks/test"
 )
 
@@ -79,7 +81,7 @@ func TestUpdateLogAggregateStats(t *testing.T) {
 		if i == len(responses)-1 { // Handle last log.
 			hook = logTest.NewGlobal()
 		}
-		v.UpdateLogAggregateStats(val, types.Slot(32*(i+1)))
+		v.UpdateLogAggregateStats(val, types.Slot(params.BeaconConfig().SlotsPerEpoch*types.Slot(i+1)))
 	}
 
 	require.LogsContain(t, hook, "msg=\"Previous epoch aggregated voting summary\" attestationInclusionPct=\"67%\" "+
@@ -89,3 +91,80 @@ func TestUpdateLogAggregateStats(t *testing.T) {
 		"correctlyVotedTargetPct=\"86%\" numberOfEpochs=3 pctChangeCombinedBalance=\"0.20555%\"")
 
 }
+
+func TestUpdateLogAltairAggregateStats(t *testing.T) {
+	v := &validator{
+		logValidatorBalances: true,
+		startBalances:        make(map[[48]byte]uint64),
+		prevBalance:          make(map[[48]byte]uint64),
+		voteStats: voteStats{
+			startEpoch: params.BeaconConfig().AltairForkEpoch, // this would otherwise have been previously set in LogValidatorGainsAndLosses()
+		},
+	}
+
+	pubKeyBytes := [][48]byte{
+		bytesutil.ToBytes48([]byte("000000000000000000000000000000000000000012345678")),
+		bytesutil.ToBytes48([]byte("000000000000000000000000000000000000000099999999")),
+		bytesutil.ToBytes48([]byte("000000000000000000000000000000000000000055555555")),
+	}
+
+	v.startBalances[pubKeyBytes[0]] = uint64(32100000000)
+	v.startBalances[pubKeyBytes[1]] = uint64(32200000000)
+	v.startBalances[pubKeyBytes[2]] = uint64(33000000000)
+
+	// 7 attestations included
+	responses := []*ethpb.ValidatorPerformanceResponse{
+		{
+			PublicKeys: [][]byte{
+				bytesutil.FromBytes48(pubKeyBytes[0]),
+				bytesutil.FromBytes48(pubKeyBytes[1]),
+				bytesutil.FromBytes48(pubKeyBytes[2]),
+			},
+			CorrectlyVotedHead:   []bool{false, true, false},
+			CorrectlyVotedSource: []bool{false, true, true},
+			CorrectlyVotedTarget: []bool{false, false, true}, // test one fast target that is included
+		},
+		{
+			PublicKeys: [][]byte{
+				bytesutil.FromBytes48(pubKeyBytes[0]),
+				bytesutil.FromBytes48(pubKeyBytes[1]),
+				bytesutil.FromBytes48(pubKeyBytes[2]),
+			},
+			CorrectlyVotedHead:   []bool{true, true, true},
+			CorrectlyVotedSource: []bool{true, true, true},
+			CorrectlyVotedTarget: []bool{true, true, true},
+		},
+		{
+			PublicKeys: [][]byte{
+				bytesutil.FromBytes48(pubKeyBytes[0]),
+				bytesutil.FromBytes48(pubKeyBytes[1]),
+				bytesutil.FromBytes48(pubKeyBytes[2]),
+			},
+			CorrectlyVotedHead:   []bool{true, false, true},
+			CorrectlyVotedSource: []bool{true, false, true},
+			CorrectlyVotedTarget: []bool{false, false, true},
+		},
+	}
+
+	v.prevBalance[pubKeyBytes[0]] = uint64(33200000000)
+	v.prevBalance[pubKeyBytes[1]] = uint64(33300000000)
+	v.prevBalance[pubKeyBytes[2]] = uint64(31000000000)
+
+	var hook *logTest.Hook
+
+	for i, val := range responses {
+		if i == len(responses)-1 { // Handle last log.
+			hook = logTest.NewGlobal()
+		}
+		altairStart, err := slots.EpochStart(params.BeaconConfig().AltairForkEpoch)
+		require.NoError(t, err)
+
+		v.UpdateLogAggregateStats(val, altairStart+params.BeaconConfig().SlotsPerEpoch*types.Slot(i+1))
+	}
+
+	require.LogsContain(t, hook, "msg=\"Previous epoch aggregated voting summary\" attestationInclusionPct=\"67%\" "+
+		"averageInactivityScore=0 correctlyVotedHeadPct=\"100%\" correctlyVotedSourcePct=\"100%\" correctlyVotedTargetPct=\"50%\" epoch=74242")
+	require.LogsContain(t, hook, "msg=\"Vote summary since launch\" attestationsInclusionPct=\"78%\" "+
+		"correctlyVotedHeadPct=\"86%\" correctlyVotedSourcePct=\"100%\" "+
+		"correctlyVotedTargetPct=\"71%\" numberOfEpochs=3 pctChangeCombinedBalance=\"0.20555%\"")
+}

validator/client/validator.go

@@ -849,13 +849,10 @@ func validatorSubscribeKey(slot types.Slot, committeeID types.CommitteeIndex) [6
 // This tracks all validators' voting status.
 type voteStats struct {
 	startEpoch          types.Epoch
-	includedAttestedCount uint64
 	totalAttestedCount  uint64
+	totalRequestedCount uint64
 	totalDistance       types.Slot
-	correctSources        uint64
+	totalCorrectSource  uint64
-	totalSources          uint64
+	totalCorrectTarget  uint64
-	correctTargets        uint64
+	totalCorrectHead    uint64
-	totalTargets          uint64
-	correctHeads          uint64
-	totalHeads            uint64
 }