From 14f6d170b27a262a93a310ec99a6e20cf05e9b95 Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Tue, 4 May 2021 18:18:26 +0200 Subject: [PATCH 1/3] Add a mining-heartbeat INFO line at every epoch --- chain/gen/gen.go | 9 +++++++++ miner/miner.go | 34 ++++++++++++++++++++++++++++++++-- 2 files changed, 41 insertions(+), 2 deletions(-) diff --git a/chain/gen/gen.go b/chain/gen/gen.go index d06c755fa34..a6bf1b2b1c9 100644 --- a/chain/gen/gen.go +++ b/chain/gen/gen.go @@ -3,6 +3,7 @@ package gen import ( "bytes" "context" + "encoding/base64" "fmt" "io" "io/ioutil" @@ -610,6 +611,8 @@ func (wpp *wppProvider) ComputeProof(context.Context, []proof2.SectorInfo, abi.P return ValidWpostForTesting, nil } +var b64 = base64.URLEncoding.WithPadding(base64.NoPadding) + func IsRoundWinner(ctx context.Context, ts *types.TipSet, round abi.ChainEpoch, miner address.Address, brand types.BeaconEntry, mbi *api.MiningBaseInfo, a MiningCheckAPI) (*types.ElectionProof, error) { @@ -631,6 +634,12 @@ func IsRoundWinner(ctx context.Context, ts *types.TipSet, round abi.ChainEpoch, ep := &types.ElectionProof{VRFProof: vrfout} j := ep.ComputeWinCount(mbi.MinerPower, mbi.NetworkPower) ep.WinCount = j + + log.Infow("completed winAttemptVRF", + "VRFb64", b64.EncodeToString(vrfout), + "winCount", j, + ) + if j < 1 { return nil, nil } diff --git a/miner/miner.go b/miner/miner.go index eb7dd95f54d..1e6ff2792eb 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -11,6 +11,7 @@ import ( proof2 "github.com/filecoin-project/specs-actors/v2/actors/runtime/proof" + "github.com/filecoin-project/lotus/chain/actors/policy" "github.com/filecoin-project/lotus/chain/gen/slashfilter" "github.com/filecoin-project/go-address" @@ -423,8 +424,37 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, return nil, xerrors.Errorf("failed to get mining base info: %w", err) } if mbi == nil { + log.Warnf("mineOne: unexpectedly nil MiningBaseInfo for round %d, off tipset %d/%s", round, base.TipSet.Height(), base.TipSet.Key().String()) return nil, nil } + + // always write out a log from this point out + var winner *types.ElectionProof + lookBack := make(chan int64) + + // figure this out in the background, instead of slowing down the main loop + go func() { + lb := int64(-1) + if netVer, err := m.api.StateNetworkVersion(ctx, base.TipSet.Key()); err == nil { + lb = int64(policy.GetWinningPoStSectorSetLookback(netVer)) + } + lookBack <- lb + }() + + defer func() { + + log.Infow( + "completed mineOne", + "forRound", int64(round), + "baseEpoch", int64(base.TipSet.Height()), + "lookbackEpochs", <-lookBack, + "networkPowerAtLookback", mbi.NetworkPower.String(), + "minerPowerAtLookback", mbi.MinerPower.String(), + "isEligible", mbi.EligibleForMining, + "isWinner", (winner != nil), + ) + }() + if !mbi.EligibleForMining { // slashed or just have no power yet return nil, nil @@ -451,7 +481,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, return nil, xerrors.Errorf("scratching ticket failed: %w", err) } - winner, err := gen.IsRoundWinner(ctx, base.TipSet, round, m.address, rbase, mbi, m.api) + winner, err = gen.IsRoundWinner(ctx, base.TipSet, round, m.address, rbase, mbi, m.api) if err != nil { return nil, xerrors.Errorf("failed to check if we win next round: %w", err) } @@ -503,7 +533,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, for i, header := range base.TipSet.Blocks() { parentMiners[i] = header.Miner } - log.Infow("mined new block", "cid", b.Cid(), "height", b.Header.Height, "miner", b.Header.Miner, "parents", parentMiners, "took", dur) + log.Infow("mined new block", "cid", b.Cid(), "height", int64(b.Header.Height), "miner", b.Header.Miner, "parents", parentMiners, "parentTipset", base.TipSet.Key().String(), "took", dur) if dur > time.Second*time.Duration(build.BlockDelaySecs) { log.Warnw("CAUTION: block production took longer than the block delay. Your computer may not be fast enough to keep up", "tMinerBaseInfo ", tMBI.Sub(start), From 3b0fc01e820f4d55d1b54dc73e12927d56172b49 Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Wed, 5 May 2021 20:39:16 +0200 Subject: [PATCH 2/3] Log more ComputeVRF() inputs as per Why's request --- chain/gen/gen.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/chain/gen/gen.go b/chain/gen/gen.go index a6bf1b2b1c9..b4e04424c11 100644 --- a/chain/gen/gen.go +++ b/chain/gen/gen.go @@ -636,7 +636,10 @@ func IsRoundWinner(ctx context.Context, ts *types.TipSet, round abi.ChainEpoch, ep.WinCount = j log.Infow("completed winAttemptVRF", - "VRFb64", b64.EncodeToString(vrfout), + "beaconRound", brand.Round, + "beaconDataB64", b64.EncodeToString(brand.Data), + "electionRandB64", b64.EncodeToString(electionRand), + "vrfB64", b64.EncodeToString(vrfout), "winCount", j, ) From 26841aa09430b3d6d8be013e890ce31f913fef9f Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Wed, 5 May 2021 22:54:01 +0200 Subject: [PATCH 3/3] mining lookback is effectively a constant - make it so --- chain/actors/policy/policy.go | 1 + miner/miner.go | 14 +------------- 2 files changed, 2 insertions(+), 13 deletions(-) diff --git a/chain/actors/policy/policy.go b/chain/actors/policy/policy.go index f210b8d94a7..07f489b11b1 100644 --- a/chain/actors/policy/policy.go +++ b/chain/actors/policy/policy.go @@ -187,6 +187,7 @@ func GetWinningPoStSectorSetLookback(nwVer network.Version) abi.ChainEpoch { return 10 } + // NOTE: if this ever changes, adjust it in a (*Miner).mineOne() logline as well return ChainFinality } diff --git a/miner/miner.go b/miner/miner.go index 1e6ff2792eb..2ad0f638e07 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -430,24 +430,12 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, // always write out a log from this point out var winner *types.ElectionProof - lookBack := make(chan int64) - - // figure this out in the background, instead of slowing down the main loop - go func() { - lb := int64(-1) - if netVer, err := m.api.StateNetworkVersion(ctx, base.TipSet.Key()); err == nil { - lb = int64(policy.GetWinningPoStSectorSetLookback(netVer)) - } - lookBack <- lb - }() - defer func() { - log.Infow( "completed mineOne", "forRound", int64(round), "baseEpoch", int64(base.TipSet.Height()), - "lookbackEpochs", <-lookBack, + "lookbackEpochs", int64(policy.ChainFinality), // hardcoded as it is unlikely to change again: https://github.com/filecoin-project/lotus/blob/v1.8.0/chain/actors/policy/policy.go#L180-L186 "networkPowerAtLookback", mbi.NetworkPower.String(), "minerPowerAtLookback", mbi.MinerPower.String(), "isEligible", mbi.EligibleForMining,