Merge pull request #1900 from filecoin-project/feat/subcall-timing-compute-state

add subcall timing to compute state output

chain/types/execresult.go

@@ -1,9 +1,12 @@
 package types
 
+import "time"
+
 type ExecutionResult struct {
-	Msg    *Message
-	MsgRct *MessageReceipt
-	Error  string
+	Msg      *Message
+	MsgRct   *MessageReceipt
+	Error    string
+	Duration time.Duration
 
 	Subcalls []*ExecutionResult
 }

chain/vm/runtime.go

@@ -5,6 +5,8 @@ import (
 	"context"
 	"encoding/binary"
 	"fmt"
+	"time"
+
 	"github.com/filecoin-project/go-address"
 	"github.com/filecoin-project/specs-actors/actors/abi"
 	"github.com/filecoin-project/specs-actors/actors/abi/big"
@@ -366,6 +368,7 @@ func (rs *Runtime) Send(to address.Address, method abi.MethodNum, m vmr.CBORMars
 }
 
 func (rt *Runtime) internalSend(from, to address.Address, method abi.MethodNum, value types.BigInt, params []byte) ([]byte, aerrors.ActorError) {
+	start := time.Now()
 	ctx, span := trace.StartSpan(rt.ctx, "vmc.Send")
 	defer span.End()
 	if span.IsRecordingEvents() {
@@ -405,8 +408,9 @@ func (rt *Runtime) internalSend(from, to address.Address, method abi.MethodNum,
 	}
 
 	er := types.ExecutionResult{
-		Msg:    msg,
-		MsgRct: &mr,
+		Msg:      msg,
+		MsgRct:   &mr,
+		Duration: time.Since(start),
 	}
 
 	if errSend != nil {

cli/state.go

@@ -1082,12 +1082,15 @@ func printInternalExecutionsHtml(trace []*types.ExecutionResult, getCode func(ad
 			ret = `, Return</div><div><pre class="ret">` + ret + `</pre></div>`
 		}
 
+		slow := im.Duration > 10*time.Millisecond
+		veryslow := im.Duration > 50*time.Millisecond
+
 		fmt.Printf(`<div class="exec">
 <div><h4 class="call">%s:%s</h4></div>
 <div><b>%s</b> -&gt; <b>%s</b> (%s FIL), M%d</div>
 %s
-<div><span class="exit%d">Exit: <b>%d</b></span>%s
-`, codeStr(toCode), methods[toCode][im.Msg.Method].name, im.Msg.From, im.Msg.To, types.FIL(im.Msg.Value), im.Msg.Method, params, im.MsgRct.ExitCode, im.MsgRct.ExitCode, ret)
+<div><span class="slow-%t-%t">Took %s</span>, <span class="exit%d">Exit: <b>%d</b></span>%s
+`, codeStr(toCode), methods[toCode][im.Msg.Method].name, im.Msg.From, im.Msg.To, types.FIL(im.Msg.Value), im.Msg.Method, params, slow, veryslow, im.Duration, im.MsgRct.ExitCode, im.MsgRct.ExitCode, ret)
 		if im.MsgRct.ExitCode != 0 {
 			fmt.Printf(`<div class="error">Error: <pre>%s</pre></div>`, im.Error)
 		}

cmd/lotus-storage-miner/proving.go

@@ -3,6 +3,8 @@ package main
 import (
 	"bytes"
 	"fmt"
+	"time"
+
 	"github.com/filecoin-project/lotus/build"
 	"github.com/filecoin-project/lotus/chain/types"
 	lcli "github.com/filecoin-project/lotus/cli"
@@ -10,7 +12,6 @@ import (
 	"github.com/filecoin-project/specs-actors/actors/builtin/miner"
 	"golang.org/x/xerrors"
 	"gopkg.in/urfave/cli.v2"
-	"time"
 )
 
 var provingCmd = &cli.Command{