From 2d15e925cd2df3ab76d7657622e68fd10fff1350 Mon Sep 17 00:00:00 2001
From: whyrusleeping <why@ipfs.io>
Date: Tue, 3 Dec 2019 12:00:04 -0800
Subject: [PATCH] WIP: improve timing of mining

---
 chain/sync.go      |  3 +++
 miner/miner.go     | 30 +++++++++++++++++++++---------
 miner/testminer.go |  4 ++--
 3 files changed, 26 insertions(+), 11 deletions(-)

diff --git a/chain/sync.go b/chain/sync.go
index b98a1fddb..f5d9d8724 100644
--- a/chain/sync.go
+++ b/chain/sync.go
@@ -538,6 +538,9 @@ func (syncer *Syncer) ValidateBlock(ctx context.Context, b *types.FullBlock) err
 	if h.Timestamp > uint64(time.Now().Unix()+build.AllowableClockDrift) {
 		return xerrors.Errorf("block was from the future")
 	}
+	if h.Timestamp > uint64(time.Now().Unix()) {
+		log.Warn("Got block from the future, but within threshold", h.Timestamp, time.Now().Unix())
+	}
 
 	if h.Timestamp < baseTs.MinTimestamp()+(build.BlockDelay*(h.Height-baseTs.Height())) {
 		log.Warn("timestamp funtimes: ", h.Timestamp, baseTs.MinTimestamp(), h.Height, baseTs.Height())
diff --git a/miner/miner.go b/miner/miner.go
index b49c422d5..0b8d2f9f5 100644
--- a/miner/miner.go
+++ b/miner/miner.go
@@ -19,15 +19,17 @@ import (
 
 var log = logging.Logger("miner")
 
-type waitFunc func(ctx context.Context) error
+type waitFunc func(ctx context.Context, baseTime uint64) error
 
 func NewMiner(api api.FullNode, epp gen.ElectionPoStProver) *Miner {
 	return &Miner{
 		api: api,
 		epp: epp,
-		waitFunc: func(ctx context.Context) error {
+		waitFunc: func(ctx context.Context, baseTime uint64) error {
 			// Wait around for half the block time in case other parents come in
-			time.Sleep(build.PropagationDelay * time.Second)
+			deadline := baseTime + build.PropagationDelay
+			time.Sleep(time.Until(time.Unix(int64(deadline), 0)))
+
 			return nil
 		},
 	}
@@ -141,8 +143,15 @@ eventLoop:
 		addrs := m.addresses
 		m.lk.Unlock()
 
-		// Sleep a small amount in order to wait for other blocks to arrive
-		if err := m.waitFunc(ctx); err != nil {
+		prebase, err := m.GetBestMiningCandidate(ctx)
+		if err != nil {
+			log.Errorf("failed to get best mining candidate: %s", err)
+			time.Sleep(time.Second * 5)
+			continue
+		}
+
+		// Wait until propagation delay period after block we plan to mine on
+		if err := m.waitFunc(ctx, prebase.ts.MinTimestamp()); err != nil {
 			log.Error(err)
 			return
 		}
@@ -159,6 +168,8 @@ eventLoop:
 		}
 		lastBase = *base
 
+		log.Infof("Time delta between now and our mining base: %ds", uint64(time.Now().Unix())-base.ts.MinTimestamp())
+
 		blks := make([]*types.BlockMsg, 0)
 
 		for _, addr := range addrs {
@@ -289,10 +300,9 @@ func (m *Miner) mineOne(ctx context.Context, addr address.Address, base *MiningB
 	if err != nil {
 		return nil, xerrors.Errorf("failed to create block: %w", err)
 	}
-	log.Infow("mined new block", "cid", b.Cid(), "height", b.Header.Height)
 
-	dur := time.Now().Sub(start)
-	log.Infof("Creating block took %s", dur)
+	dur := time.Since(start)
+	log.Infow("mined new block", "cid", b.Cid(), "height", b.Header.Height, "took", dur)
 	if dur > time.Second*build.BlockDelay {
 		log.Warn("CAUTION: block production took longer than the block delay. Your computer may not be fast enough to keep up")
 	}
@@ -374,6 +384,7 @@ func selectMessages(ctx context.Context, al actorLookup, base *MiningBase, msgs
 	out := make([]*types.SignedMessage, 0, len(msgs))
 	inclNonces := make(map[address.Address]uint64)
 	inclBalances := make(map[address.Address]types.BigInt)
+	inclCount := make(map[address.Address]int)
 
 	for _, msg := range msgs {
 		if msg.Message.To == address.Undef {
@@ -399,7 +410,7 @@ func selectMessages(ctx context.Context, al actorLookup, base *MiningBase, msgs
 		}
 
 		if msg.Message.Nonce > inclNonces[from] {
-			log.Warnf("message in mempool has too high of a nonce (%d > %d) %s (%d pending for orig)", msg.Message.Nonce, inclNonces[from], msg.Cid(), countFrom(msgs, from))
+			log.Warnf("message in mempool has too high of a nonce (%d > %d, from %s, inclcount %d) %s (%d pending for orig)", msg.Message.Nonce, inclNonces[from], from, inclCount[from], msg.Cid(), countFrom(msgs, from))
 			continue
 		}
 
@@ -410,6 +421,7 @@ func selectMessages(ctx context.Context, al actorLookup, base *MiningBase, msgs
 
 		inclNonces[from] = msg.Message.Nonce + 1
 		inclBalances[from] = types.BigSub(inclBalances[from], msg.Message.RequiredFunds())
+		inclCount[from]++
 
 		out = append(out, msg)
 	}
diff --git a/miner/testminer.go b/miner/testminer.go
index 594f2175e..1f93eb04f 100644
--- a/miner/testminer.go
+++ b/miner/testminer.go
@@ -23,8 +23,8 @@ func NewTestMiner(nextCh <-chan struct{}, addr address.Address) func(api.FullNod
 	}
 }
 
-func chanWaiter(next <-chan struct{}) func(ctx context.Context) error {
-	return func(ctx context.Context) error {
+func chanWaiter(next <-chan struct{}) func(ctx context.Context, _ uint64) error {
+	return func(ctx context.Context, _ uint64) error {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()