add a command to lotus-bench to benchmark importing and validating a chain

api/api_full.go

@@ -314,6 +314,7 @@ type InvocResult struct {
 	MsgRct             *types.MessageReceipt
 	InternalExecutions []*vm.ExecutionResult
 	Error              string
+	Duration           time.Duration
 }
 
 type MethodCall struct {

chain/stmgr/call.go

@@ -68,6 +68,7 @@ func (sm *StateManager) CallRaw(ctx context.Context, msg *types.Message, bstate
 		MsgRct:             &ret.MessageReceipt,
 		InternalExecutions: ret.InternalExecutions,
 		Error:              errs,
+		Duration:           ret.Duration,
 	}, nil
 
 }

chain/stmgr/stmgr.go

@@ -124,6 +124,7 @@ func (sm *StateManager) ExecutionTrace(ctx context.Context, ts *types.TipSet) (c
 			Msg:                msg,
 			MsgRct:             &ret.MessageReceipt,
 			InternalExecutions: ret.InternalExecutions,
+			Duration:           ret.Duration,
 		}
 		if ret.ActorErr != nil {
 			ir.Error = ret.ActorErr.Error()

chain/vm/vm.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"fmt"
 	"reflect"
+	"time"
 
 	"github.com/filecoin-project/specs-actors/actors/builtin"
 
@@ -186,6 +187,7 @@ type ApplyRet struct {
 	ActorErr           aerrors.ActorError
 	Penalty            types.BigInt
 	InternalExecutions []*ExecutionResult
+	Duration           time.Duration
 }
 
 func (vm *VM) send(ctx context.Context, msg *types.Message, parent *Runtime,
@@ -261,6 +263,7 @@ func checkMessage(msg *types.Message) error {
 }
 
 func (vm *VM) ApplyImplicitMessage(ctx context.Context, msg *types.Message) (*ApplyRet, error) {
+	start := time.Now()
 	ret, actorErr, _ := vm.send(ctx, msg, nil, 0)
 	return &ApplyRet{
 		MessageReceipt: types.MessageReceipt{
@@ -271,10 +274,12 @@ func (vm *VM) ApplyImplicitMessage(ctx context.Context, msg *types.Message) (*Ap
 		ActorErr:           actorErr,
 		InternalExecutions: nil,
 		Penalty:            types.NewInt(0),
+		Duration:           time.Since(start),
 	}, actorErr
 }
 
 func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet, error) {
+	start := time.Now()
 	ctx, span := trace.StartSpan(ctx, "vm.ApplyMessage")
 	defer span.End()
 	msg := cmsg.VMMessage()
@@ -300,6 +305,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 				GasUsed:  0,
 			},
 			Penalty:  types.BigMul(msg.GasPrice, types.NewInt(uint64(msgGasCost))),
+			Duration: time.Since(start),
 		}, nil
 	}
 
@@ -315,6 +321,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 					GasUsed:  0,
 				},
 				Penalty:  minerPenaltyAmount,
+				Duration: time.Since(start),
 			}, nil
 		}
 		return nil, xerrors.Errorf("failed to look up from actor: %w", err)
@@ -327,6 +334,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 				GasUsed:  0,
 			},
 			Penalty:  minerPenaltyAmount,
+			Duration: time.Since(start),
 		}, nil
 	}
 
@@ -337,6 +345,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 				GasUsed:  0,
 			},
 			Penalty:  minerPenaltyAmount,
+			Duration: time.Since(start),
 		}, nil
 	}
 
@@ -349,6 +358,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 				GasUsed:  0,
 			},
 			Penalty:  minerPenaltyAmount,
+			Duration: time.Since(start),
 		}, nil
 	}
 
@@ -423,6 +433,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 		ActorErr:           actorErr,
 		InternalExecutions: rt.internalExecutions,
 		Penalty:            types.NewInt(0),
+		Duration:           time.Since(start),
 	}, nil
 }
 

cmd/lotus-bench/import.go

@@ -0,0 +1,140 @@
+package main
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+	"io/ioutil"
+	"os"
+	"runtime/pprof"
+	"time"
+
+	"github.com/filecoin-project/lotus/api"
+	"github.com/filecoin-project/lotus/chain/stmgr"
+	"github.com/filecoin-project/lotus/chain/store"
+	"github.com/filecoin-project/lotus/chain/types"
+	"github.com/filecoin-project/lotus/chain/vm"
+	"github.com/filecoin-project/sector-storage/ffiwrapper"
+	"github.com/filecoin-project/specs-actors/actors/abi"
+	"golang.org/x/xerrors"
+
+	"github.com/ipfs/go-datastore"
+	badger "github.com/ipfs/go-ds-badger2"
+	blockstore "github.com/ipfs/go-ipfs-blockstore"
+	"gopkg.in/urfave/cli.v2"
+)
+
+type TipSetExec struct {
+	TipSet   types.TipSetKey
+	Trace    []*api.InvocResult
+	Duration time.Duration
+}
+
+var importBenchCmd = &cli.Command{
+	Name:  "import",
+	Usage: "benchmark chain import and validation",
+	Flags: []cli.Flag{
+		&cli.Int64Flag{
+			Name:  "height",
+			Usage: "halt validation after given height",
+		},
+	},
+	Action: func(cctx *cli.Context) error {
+		if !cctx.Args().Present() {
+			fmt.Println("must pass car file of chain to benchmark importing")
+			return nil
+		}
+
+		cfi, err := os.Open(cctx.Args().First())
+		if err != nil {
+			return err
+		}
+		defer cfi.Close()
+
+		tdir, err := ioutil.TempDir("", "lotus-import-bench")
+		if err != nil {
+			return err
+		}
+
+		bds, err := badger.NewDatastore(tdir, nil)
+		if err != nil {
+			return err
+		}
+		bs := blockstore.NewBlockstore(bds)
+		ds := datastore.NewMapDatastore()
+		cs := store.NewChainStore(bs, ds, vm.Syscalls(ffiwrapper.ProofVerifier))
+		stm := stmgr.NewStateManager(cs)
+
+		prof, err := os.Create("import-bench.prof")
+		if err != nil {
+			return err
+		}
+		defer prof.Close()
+
+		if err := pprof.StartCPUProfile(prof); err != nil {
+			return err
+		}
+
+		head, err := cs.Import(cfi)
+		if err != nil {
+			return err
+		}
+
+		if h := cctx.Int64("height"); h != 0 {
+			tsh, err := cs.GetTipsetByHeight(context.TODO(), abi.ChainEpoch(h), head)
+			if err != nil {
+				return err
+			}
+			head = tsh
+		}
+
+		ts := head
+		tschain := []*types.TipSet{ts}
+		for ts.Height() != 0 {
+			next, err := cs.LoadTipSet(ts.Parents())
+			if err != nil {
+				return err
+			}
+
+			tschain = append(tschain, next)
+			ts = next
+		}
+
+		out := make([]TipSetExec, 0, len(tschain))
+
+		lastState := tschain[len(tschain)-1].ParentState()
+		for i := len(tschain) - 2; i >= 0; i-- {
+			cur := tschain[i]
+			log.Infof("computing state (height: %d, ts=%s)", cur.Height(), cur.Cids())
+			if cur.ParentState() != lastState {
+				return xerrors.Errorf("tipset chain had state mismatch at height %d", cur.Height())
+			}
+			start := time.Now()
+			st, trace, err := stm.ExecutionTrace(context.TODO(), cur)
+			if err != nil {
+				return err
+			}
+			out = append(out, TipSetExec{
+				TipSet:   cur.Key(),
+				Trace:    trace,
+				Duration: time.Since(start),
+			})
+			lastState = st
+		}
+
+		pprof.StopCPUProfile()
+
+		ibj, err := os.Create("import-bench.json")
+		if err != nil {
+			return err
+		}
+		defer ibj.Close()
+
+		if err := json.NewEncoder(ibj).Encode(out); err != nil {
+			return err
+		}
+
+		return nil
+
+	},
+}

cmd/lotus-bench/main.go

@@ -74,7 +74,19 @@ func main() {
 		Version: build.UserVersion,
 		Commands: []*cli.Command{
 			proveCmd,
+			sealBenchCmd,
+			importBenchCmd,
 		},
+	}
+
+	if err := app.Run(os.Args); err != nil {
+		log.Warnf("%+v", err)
+		return
+	}
+}
+
+var sealBenchCmd = &cli.Command{
+	Name: "sealing",
 	Flags: []cli.Flag{
 		&cli.StringFlag{
 			Name:  "storage-dir",
@@ -487,12 +499,6 @@ func main() {
 		}
 		return nil
 	},
-	}
-
-	if err := app.Run(os.Args); err != nil {
-		log.Warnf("%+v", err)
-		return
-	}
 }
 
 var proveCmd = &cli.Command{

go.sum

@@ -642,6 +642,7 @@ github.com/mattn/go-runewidth v0.0.7 h1:Ei8KR0497xHyKJPAv59M1dkC+rOZCMBJ+t3fZ+tw
 github.com/mattn/go-runewidth v0.0.7/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI=
 github.com/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0jegS5sx/RkqARlsWZ6pIwiU=
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
+github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b h1:j7+1HpAFS1zy5+Q4qx1fWh90gTKwiN4QCGoY9TWyyO4=
 github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b/go.mod h1:01TrycV0kFyexm33Z7vhZRXopbI8J3TDReVlkTgMUxE=
 github.com/miekg/dns v1.1.12/go.mod h1:W1PPwlIAgtquWBMBEV9nkV9Cazfe8ScdGz/Lj7v3Nrg=
 github.com/minio/blake2b-simd v0.0.0-20160723061019-3f5f724cb5b1 h1:lYpkrQH5ajf0OXOcUbGjvZxxijuBwbbmlSxLiuofa+g=
@@ -791,6 +792,7 @@ github.com/spf13/cobra v0.0.5/go.mod h1:3K3wKZymM7VvHMDS9+Akkh4K60UwM26emMESw8tL
 github.com/spf13/jwalterweatherman v1.0.0/go.mod h1:cQK4TGJAtQXfYWX+Ddv3mKDzgVb68N+wFjFa4jdeBTo=
 github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
 github.com/spf13/viper v1.3.2/go.mod h1:ZiWeW+zYFKm7srdB9IoDzzZXaJaI5eL9QjNiN/DMA2s=
+github.com/src-d/envconfig v1.0.0 h1:/AJi6DtjFhZKNx3OB2qMsq7y4yT5//AeSZIe7rk+PX8=
 github.com/src-d/envconfig v1.0.0/go.mod h1:Q9YQZ7BKITldTBnoxsE5gOeB5y66RyPXeue/R4aaNBc=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1 h1:2vfRuCMp5sSVIDSqO8oNnWJq7mPa6KVP3iPIwFBuy8A=
@@ -847,6 +849,7 @@ github.com/whyrusleeping/pubsub v0.0.0-20131020042734-02de8aa2db3d/go.mod h1:g7c
 github.com/whyrusleeping/timecache v0.0.0-20160911033111-cfcb2f1abfee h1:lYbXeSvJi5zk5GLKVuid9TVjS9a0OmLIDKTfoZBL6Ow=
 github.com/whyrusleeping/timecache v0.0.0-20160911033111-cfcb2f1abfee/go.mod h1:m2aV4LZI4Aez7dP5PMyVKEHhUyEJ/RjmPEDOpDvudHg=
 github.com/whyrusleeping/yamux v1.1.5/go.mod h1:E8LnQQ8HKx5KD29HZFUwM1PxCOdPRzGwur1mcYhXcD8=
+github.com/x-cray/logrus-prefixed-formatter v0.5.2 h1:00txxvfBM9muc0jiLIEAkAcIMJzfthRT6usrui8uGmg=
 github.com/x-cray/logrus-prefixed-formatter v0.5.2/go.mod h1:2duySbKsL6M18s5GU7VPsoEPHyzalCE06qoARUCeBBE=
 github.com/xordataexchange/crypt v0.0.3-0.20170626215501-b2862e3d0a77/go.mod h1:aYKd//L2LvnjZzWKhF00oedf4jCCReLcmhLdhm1A27Q=
 github.com/yuin/goldmark v1.1.25/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
@@ -1035,6 +1038,7 @@ gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI=
 gopkg.in/fsnotify.v1 v1.4.7 h1:xOHLXZwVvI9hhs+cLKq5+I5onOuwQLhQwiu63xxlHs4=
 gopkg.in/fsnotify.v1 v1.4.7/go.mod h1:Tz8NjZHkW78fSQdbUxIjBTcgA1z1m8ZHf0WmKUhAMys=
 gopkg.in/src-d/go-cli.v0 v0.0.0-20181105080154-d492247bbc0d/go.mod h1:z+K8VcOYVYcSwSjGebuDL6176A1XskgbtNl64NSg+n8=
+gopkg.in/src-d/go-log.v1 v1.0.1 h1:heWvX7J6qbGWbeFS/aRmiy1eYaT+QMV6wNvHDyMjQV4=
 gopkg.in/src-d/go-log.v1 v1.0.1/go.mod h1:GN34hKP0g305ysm2/hctJ0Y8nWP3zxXXJ8GFabTyABE=
 gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 h1:uRGJdciOHaEIrze2W8Q3AKkepLTh2hOroT7a+7czfdQ=
 gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7/go.mod h1:dt/ZhP58zS4L8KSrWDmTeBkI65Dw0HsyUHuEVlX15mw=

node/impl/full/state.go

@@ -193,6 +193,7 @@ func (a *StateAPI) StateReplay(ctx context.Context, tsk types.TipSetKey, mc cid.
 		MsgRct:             &r.MessageReceipt,
 		InternalExecutions: r.InternalExecutions,
 		Error:              errstr,
+		Duration:           r.Duration,
 	}, nil
 }