Add gas tracing

Signed-off-by: Jakub Sztandera <kubuxu@protocol.ai>

chain/sync.go

@@ -857,7 +857,7 @@ func (syncer *Syncer) checkBlockMessages(ctx context.Context, b *types.FullBlock
 
 		// Phase 1: syntactic validation, as defined in the spec
 		minGas := vm.PricelistByEpoch(baseTs.Height()).OnChainMessage(msg.ChainLength())
-		if err := m.ValidForBlockInclusion(minGas); err != nil {
+		if err := m.ValidForBlockInclusion(minGas.Total()); err != nil {
 			return err
 		}
 

chain/types/execresult.go

@@ -1,12 +1,57 @@
 package types
 
-import "time"
+import (
+	"encoding/json"
+	"fmt"
+	"runtime"
+	"strings"
+	"time"
+)
 
 type ExecutionTrace struct {
 	Msg        *Message
 	MsgRct     *MessageReceipt
 	Error      string
 	Duration   time.Duration
+	GasCharges []*GasTrace
 
 	Subcalls []ExecutionTrace
 }
+
+type GasTrace struct {
+	Name       string
+	Location   string
+	TotalGas   int64
+	ComputeGas int64
+	StorageGas int64
+
+	TimeTaken time.Duration
+
+	Callers []uintptr `json:"-"`
+}
+
+func (gt *GasTrace) MarshalJSON() ([]byte, error) {
+	type GasTraceCopy GasTrace
+	if gt.Location == "" {
+		if len(gt.Callers) != 0 {
+			frames := runtime.CallersFrames(gt.Callers)
+			for {
+				frame, more := frames.Next()
+				fn := strings.Split(frame.Function, "/")
+
+				split := strings.Split(frame.File, "/")
+				file := strings.Join(split[len(split)-2:], "/")
+				gt.Location += fmt.Sprintf("%s@%s:%d", fn[len(fn)-1], file, frame.Line)
+				if !more {
+					break
+				}
+				gt.Location += "|"
+			}
+		} else {
+			gt.Location = "n/a"
+		}
+	}
+
+	cpy := (*GasTraceCopy)(gt)
+	return json.Marshal(cpy)
+}

chain/vm/runtime.go

@@ -5,6 +5,8 @@ import (
 	"context"
 	"encoding/binary"
 	"fmt"
+	gruntime "runtime"
+	"time"
 
 	"github.com/filecoin-project/go-address"
 	"github.com/filecoin-project/specs-actors/actors/abi"
@@ -54,6 +56,8 @@ type Runtime struct {
 	numActorsCreated  uint64
 	allowInternal     bool
 	callerValidated   bool
+	lastGasChargeTime time.Time
+	lastGasCharge     *types.GasTrace
 }
 
 func (rt *Runtime) TotalFilCircSupply() abi.TokenAmount {
@@ -392,7 +396,7 @@ func (rt *Runtime) internalSend(from, to address.Address, method abi.MethodNum,
 	}
 	defer st.ClearSnapshot()
 
-	ret, errSend, subrt := rt.vm.send(ctx, msg, rt, 0)
+	ret, errSend, subrt := rt.vm.send(ctx, msg, rt, nil)
 	if errSend != nil {
 		if errRevert := st.Revert(); errRevert != nil {
 			return nil, aerrors.Escalate(errRevert, "failed to revert state tree after failed subcall")
@@ -490,9 +494,33 @@ func (rt *Runtime) ChargeGas(gas GasCharge) {
 		panic(err)
 	}
 }
+func (rt *Runtime) finilizeGasTracing() {
+	if rt.lastGasCharge != nil {
+		rt.lastGasCharge.TimeTaken = time.Since(rt.lastGasChargeTime)
+	}
+}
 
 func (rt *Runtime) chargeGasInternal(gas GasCharge) aerrors.ActorError {
 	toUse := gas.Total()
+	var callers [3]uintptr
+	cout := gruntime.Callers(3, callers[:])
+
+	now := time.Now()
+	if rt.lastGasCharge != nil {
+		rt.lastGasCharge.TimeTaken = now.Sub(rt.lastGasChargeTime)
+	}
+
+	gasTrace := types.GasTrace{
+		Name:       gas.Name,
+		TotalGas:   toUse,
+		ComputeGas: gas.ComputeGas,
+		StorageGas: gas.StorageGas,
+		Callers:    callers[:cout],
+	}
+	rt.executionTrace.GasCharges = append(rt.executionTrace.GasCharges, &gasTrace)
+	rt.lastGasChargeTime = now
+	rt.lastGasCharge = &gasTrace
+
 	if rt.gasUsed+toUse > rt.gasAvailable {
 		rt.gasUsed = rt.gasAvailable
 		return aerrors.Newf(exitcode.SysErrOutOfGas, "not enough gas: used=%d, available=%d", rt.gasUsed, rt.gasAvailable)

chain/vm/vm.go

@@ -103,6 +103,7 @@ func (vm *VM) makeRuntime(ctx context.Context, msg *types.Message, origin addres
 		allowInternal:     true,
 		callerValidated:   false,
 		executionTrace:    types.ExecutionTrace{Msg: msg},
+		lastGasChargeTime: time.Now(),
 	}
 
 	rt.cst = &cbor.BasicIpldStore{
@@ -171,17 +172,17 @@ type ApplyRet struct {
 }
 
 func (vm *VM) send(ctx context.Context, msg *types.Message, parent *Runtime,
-	gasCharge int64) ([]byte, aerrors.ActorError, *Runtime) {
+	gasCharge *GasCharge) ([]byte, aerrors.ActorError, *Runtime) {
 	start := time.Now()
 
 	st := vm.cstate
-	gasUsed := gasCharge
 
 	origin := msg.From
 	on := msg.Nonce
 	var nac uint64 = 0
+	var gasUsed int64
 	if parent != nil {
-		gasUsed = parent.gasUsed + gasUsed
+		gasUsed = parent.gasUsed
 		origin = parent.origin
 		on = parent.originNonce
 		nac = parent.numActorsCreated
@@ -189,11 +190,22 @@ func (vm *VM) send(ctx context.Context, msg *types.Message, parent *Runtime,
 
 	rt := vm.makeRuntime(ctx, msg, origin, on, gasUsed, nac)
 	if parent != nil {
+		rt.lastGasChargeTime = parent.lastGasChargeTime
+		rt.lastGasCharge = parent.lastGasCharge
 		defer func() {
 			parent.gasUsed = rt.gasUsed
+			parent.lastGasChargeTime = rt.lastGasChargeTime
+			parent.lastGasCharge = rt.lastGasCharge
 		}()
 	}
 
+	if gasCharge != nil {
+		if err := rt.chargeGasSafe(*gasCharge); err != nil {
+			// this should never happen
+			return nil, aerrors.Wrap(err, "not enough gas for initial message charge, this should not happen"), rt
+		}
+	}
+
 	ret, err := func() ([]byte, aerrors.ActorError) {
 		if aerr := rt.chargeGasSafe(rt.Pricelist().OnMethodInvocation(msg.Value, msg.Method)); aerr != nil {
 			return nil, aerrors.Wrap(aerr, "not enough gas for method invocation")
@@ -261,7 +273,7 @@ func checkMessage(msg *types.Message) error {
 
 func (vm *VM) ApplyImplicitMessage(ctx context.Context, msg *types.Message) (*ApplyRet, error) {
 	start := time.Now()
-	ret, actorErr, rt := vm.send(ctx, msg, nil, 0)
+	ret, actorErr, rt := vm.send(ctx, msg, nil, nil)
 	return &ApplyRet{
 		MessageReceipt: types.MessageReceipt{
 			ExitCode: aerrors.RetCode(actorErr),
@@ -294,7 +306,8 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 
 	pl := PricelistByEpoch(vm.blockHeight)
 
-	msgGasCost := pl.OnChainMessage(cmsg.ChainLength()).Total()
+	msgGas := pl.OnChainMessage(cmsg.ChainLength())
+	msgGasCost := msgGas.Total()
 	// this should never happen, but is currently still exercised by some tests
 	if msgGasCost > msg.GasLimit {
 		return &ApplyRet{
@@ -377,7 +390,8 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 	}
 	defer st.ClearSnapshot()
 
-	ret, actorErr, rt := vm.send(ctx, msg, nil, msgGasCost)
+	ret, actorErr, rt := vm.send(ctx, msg, nil, &msgGas)
+	rt.finilizeGasTracing()
 	if aerrors.IsFatal(actorErr) {
 		return nil, xerrors.Errorf("[from=%s,to=%s,n=%d,m=%d,h=%d] fatal error: %w", msg.From, msg.To, msg.Nonce, msg.Method, vm.blockHeight, actorErr)
 	}

cli/state.go

@@ -975,6 +975,7 @@ func computeStateHtml(ts *types.TipSet, o *api.ComputeStateOutput, getCode func(
    }
    .slow-true-false { color: #660; }
    .slow-true-true { color: #f80; }
+   table { font-size: 12px; }
   </style>
  </head>
  <body>
@@ -1026,6 +1027,13 @@ func computeStateHtml(ts *types.TipSet, o *api.ComputeStateOutput, getCode func(
 		if ir.MsgRct.ExitCode != 0 {
 			fmt.Printf(`<div class="error">Error: <pre>%s</pre></div>`, ir.Error)
 		}
+		fmt.Printf("\n<details><summary>Gas Trace</summary><table><tr>" +
+			"<th>Name</th><th>Total/Compute/Storage</th><th>Time Taken</th><th>Location</th></tr>")
+		for _, gc := range ir.ExecutionTrace.GasCharges {
+			fmt.Printf("<tr><td>%s</td><td>%d/%d/%d</td><td>%s</td><td>%s</td></tr>",
+				gc.Name, gc.TotalGas, gc.ComputeGas, gc.StorageGas, gc.TimeTaken, gc.Location)
+		}
+		fmt.Printf("</table></details>\n")
 
 		fmt.Println("<div>Execution trace:</div>")
 		if err := printInternalExecutionsHtml(cid.String(), ir.ExecutionTrace.Subcalls, getCode); err != nil {
@@ -1082,6 +1090,13 @@ func printInternalExecutionsHtml(hashName string, trace []types.ExecutionTrace,
 		if im.MsgRct.ExitCode != 0 {
 			fmt.Printf(`<div class="error">Error: <pre>%s</pre></div>`, im.Error)
 		}
+		fmt.Printf("\n<details><summary>Gas Trace</summary><table><tr>" +
+			"<th>Name</th><th>Total/Compute/Storage</th><th>Time Taken</th><th>Location</th></tr>")
+		for _, gc := range im.GasCharges {
+			fmt.Printf("<tr><td>%s</td><td>%d/%d/%d</td><td>%s</td><td>%s</td></tr>",
+				gc.Name, gc.TotalGas, gc.ComputeGas, gc.StorageGas, gc.TimeTaken, gc.Location)
+		}
+		fmt.Printf("</table></details>\n")
 		if len(im.Subcalls) > 0 {
 			fmt.Println("<div>Subcalls:</div>")
 			if err := printInternalExecutionsHtml(hashName, im.Subcalls, getCode); err != nil {

miner/miner.go

@@ -485,7 +485,7 @@ func SelectMessages(ctx context.Context, al ActorLookup, ts *types.TipSet, msgs
 		vmstart := time.Now()
 
 		minGas := vm.PricelistByEpoch(ts.Height()).OnChainMessage(msg.ChainLength()) // TODO: really should be doing just msg.ChainLength() but the sync side of this code doesnt seem to have access to that
-		if err := msg.VMMessage().ValidForBlockInclusion(minGas); err != nil {
+		if err := msg.VMMessage().ValidForBlockInclusion(minGas.Total()); err != nil {
 			log.Warnf("invalid message in message pool: %s", err)
 			continue
 		}