Merge pull request #11241 from filecoin-project/asr/fix-miner-logs

fix: miner: correct duration logs in mineOne

miner/miner.go

@@ -562,7 +562,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type
 		return nil, err
 	}
 
-	tEquivocateWait := build.Clock.Now()
+	tPending := build.Clock.Now()
 
 	// This next block exists to "catch" equivocating miners,
 	// who submit 2 blocks at the same height at different times in order to split the network.
@@ -576,6 +576,8 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type
 		return nil, err
 	}
 
+	tEquivocateWait := build.Clock.Now()
+
 	// If the base has changed, we take the _intersection_ of our old base and new base,
 	// thus ejecting blocks from any equivocating miners, without taking any new blocks.
 	if newBase.TipSet.Height() == base.TipSet.Height() && !newBase.TipSet.Equals(base.TipSet) {
@@ -621,7 +623,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type
 		}
 	}
 
-	tPending := build.Clock.Now()
+	tIntersectAndRefresh := build.Clock.Now()
 
 	// TODO: winning post proof
 	minedBlock, err = m.createBlock(base, m.address, ticket, winner, bvals, postProof, msgs)
@@ -643,9 +645,10 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type
 			"tTicket ", tTicket.Sub(tPowercheck),
 			"tSeed ", tSeed.Sub(tTicket),
 			"tProof ", tProof.Sub(tSeed),
-			"tEquivocateWait ", tEquivocateWait.Sub(tProof),
-			"tPending ", tPending.Sub(tEquivocateWait),
-			"tCreateBlock ", tCreateBlock.Sub(tPending))
+			"tPending ", tPending.Sub(tProof),
+			"tEquivocateWait ", tEquivocateWait.Sub(tPending),
+			"tIntersectAndRefresh ", tIntersectAndRefresh.Sub(tEquivocateWait),
+			"tCreateBlock ", tCreateBlock.Sub(tIntersectAndRefresh))
 	}
 
 	return minedBlock, nil