Merge pull request #2011 from filecoin-project/feat/more-callers

Expose more callers, ellipsis unimportant ones

chain/types/execresult.go

@@ -20,35 +20,78 @@ type ExecutionTrace struct {
 
 type GasTrace struct {
 	Name string
-	Location   string
+
+	Location   []Loc
 	TotalGas   int64
 	ComputeGas int64
 	StorageGas int64
 
 	TimeTaken time.Duration
+	Extra     interface{}
 
 	Callers []uintptr `json:"-"`
 }
 
+type Loc struct {
+	File     string
+	Line     int
+	Function string
+}
+
+func (l Loc) Show() bool {
+	ignorePrefix := []string{
+		"reflect.",
+		"github.com/filecoin-project/lotus/chain/vm.(*Invoker).transform",
+		"github.com/filecoin-project/go-amt-ipld/",
+	}
+	for _, pre := range ignorePrefix {
+		if strings.HasPrefix(l.Function, pre) {
+			return false
+		}
+	}
+	return true
+}
+func (l Loc) String() string {
+	file := strings.Split(l.File, "/")
+
+	fn := strings.Split(l.Function, "/")
+	var fnpkg string
+	if len(fn) > 2 {
+		fnpkg = strings.Join(fn[len(fn)-2:], "/")
+	} else {
+		fnpkg = l.Function
+	}
+
+	return fmt.Sprintf("%s@%s:%d", fnpkg, file[len(file)-1], l.Line)
+}
+
+func (l Loc) Important() bool {
+	if strings.HasPrefix(l.Function, "github.com/filecoin-project/specs-actors/actors/builtin") {
+		return true
+	}
+	return false
+}
+
 func (gt *GasTrace) MarshalJSON() ([]byte, error) {
 	type GasTraceCopy GasTrace
-	if gt.Location == "" {
+	if len(gt.Location) == 0 {
 		if len(gt.Callers) != 0 {
 			frames := runtime.CallersFrames(gt.Callers)
 			for {
 				frame, more := frames.Next()
-				fn := strings.Split(frame.Function, "/")
+				if frame.Function == "github.com/filecoin-project/lotus/chain/vm.(*VM).ApplyMessage" {
-
+					break
-				split := strings.Split(frame.File, "/")
+				}
-				file := strings.Join(split[len(split)-2:], "/")
+				l := Loc{
-				gt.Location += fmt.Sprintf("%s@%s:%d", fn[len(fn)-1], file, frame.Line)
+					File:     frame.File,
+					Line:     frame.Line,
+					Function: frame.Function,
+				}
+				gt.Location = append(gt.Location, l)
 				if !more {
 					break
 				}
-				gt.Location += "|"
 			}
-		} else {
-			gt.Location = "n/a"
 		}
 	}
 

chain/vm/runtime.go

@@ -371,6 +371,8 @@ func (rt *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() {
@@ -396,7 +398,7 @@ func (rt *Runtime) internalSend(from, to address.Address, method abi.MethodNum,
 	}
 	defer st.ClearSnapshot()
 
-	ret, errSend, subrt := rt.vm.send(ctx, msg, rt, nil)
+	ret, errSend, subrt := rt.vm.send(ctx, msg, rt, nil, start)
 	if errSend != nil {
 		if errRevert := st.Revert(); errRevert != nil {
 			return nil, aerrors.Escalate(errRevert, "failed to revert state tree after failed subcall")
@@ -488,22 +490,33 @@ func (rt *Runtime) stateCommit(oldh, newh cid.Cid) aerrors.ActorError {
 	return nil
 }
 
-func (rt *Runtime) ChargeGas(gas GasCharge) {
-	err := rt.chargeGasInternal(gas)
-	if err != nil {
-		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 {
+func (rt *Runtime) ChargeGas(gas GasCharge) {
+	err := rt.chargeGasInternal(gas, 1)
+	if err != nil {
+		panic(err)
+	}
+}
+
+func (rt *Runtime) chargeGasFunc(skip int) func(GasCharge) {
+	return func(gas GasCharge) {
+		err := rt.chargeGasInternal(gas, 1+skip)
+		if err != nil {
+			panic(err)
+		}
+	}
+
+}
+
+func (rt *Runtime) chargeGasInternal(gas GasCharge, skip int) aerrors.ActorError {
 	toUse := gas.Total()
-	var callers [3]uintptr
+	var callers [10]uintptr
-	cout := gruntime.Callers(3, callers[:])
+	cout := gruntime.Callers(2+skip, callers[:])
 
 	now := time.Now()
 	if rt.lastGasCharge != nil {
@@ -530,7 +543,7 @@ func (rt *Runtime) chargeGasInternal(gas GasCharge) aerrors.ActorError {
 }
 
 func (rt *Runtime) chargeGasSafe(gas GasCharge) aerrors.ActorError {
-	return rt.chargeGasInternal(gas)
+	return rt.chargeGasInternal(gas, 1)
 }
 
 func (rt *Runtime) Pricelist() Pricelist {

chain/vm/vm.go

@@ -103,16 +103,15 @@ 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{
-		Blocks: &gasChargingBlocks{rt.ChargeGas, rt.pricelist, vm.cst.Blocks},
+		Blocks: &gasChargingBlocks{rt.chargeGasFunc(2), rt.pricelist, vm.cst.Blocks},
 		Atlas:  vm.cst.Atlas,
 	}
 	rt.sys = pricedSyscalls{
 		under:     vm.Syscalls,
-		chargeGas: rt.ChargeGas,
+		chargeGas: rt.chargeGasFunc(1),
 		pl:        rt.pricelist,
 	}
 
@@ -172,8 +171,7 @@ type ApplyRet struct {
 }
 
 func (vm *VM) send(ctx context.Context, msg *types.Message, parent *Runtime,
-	gasCharge *GasCharge) ([]byte, aerrors.ActorError, *Runtime) {
+	gasCharge *GasCharge, start time.Time) ([]byte, aerrors.ActorError, *Runtime) {
-	start := time.Now()
 
 	st := vm.cstate
 
@@ -189,6 +187,7 @@ func (vm *VM) send(ctx context.Context, msg *types.Message, parent *Runtime,
 	}
 
 	rt := vm.makeRuntime(ctx, msg, origin, on, gasUsed, nac)
+	rt.lastGasChargeTime = start
 	if parent != nil {
 		rt.lastGasChargeTime = parent.lastGasChargeTime
 		rt.lastGasCharge = parent.lastGasCharge
@@ -273,7 +272,8 @@ 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, nil)
+	ret, actorErr, rt := vm.send(ctx, msg, nil, nil, start)
+	rt.finilizeGasTracing()
 	return &ApplyRet{
 		MessageReceipt: types.MessageReceipt{
 			ExitCode: aerrors.RetCode(actorErr),
@@ -390,8 +390,7 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 	}
 	defer st.ClearSnapshot()
 
-	ret, actorErr, rt := vm.send(ctx, msg, nil, &msgGas)
+	ret, actorErr, rt := vm.send(ctx, msg, nil, &msgGas, start)
-	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)
 	}
@@ -445,6 +444,8 @@ func (vm *VM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet,
 		return nil, xerrors.Errorf("gas handling math is wrong")
 	}
 
+	rt.finilizeGasTracing()
+
 	return &ApplyRet{
 		MessageReceipt: types.MessageReceipt{
 			ExitCode: errcode,

cli/state.go

@@ -974,7 +974,39 @@ var compStateTemplate = `
     font-size: 12px;
     border-collapse: collapse;
    }
-	tr.sum { border-top: 1px solid black; }
+   tr { 
+   	border-top: 1px solid black;
+   	border-bottom: 1px solid black;
+   }
+   tr.sum { border-top: 2px solid black; }
+   tr:first-child { border-top: none; }
+   tr:last-child { border-bottom: none; }
+
+
+   .ellipsis-content,
+   .ellipsis-toggle input {
+     display: none;
+   }
+   .ellipsis-toggle {
+     cursor: pointer;
+   }
+   /**
+   Checked State
+   **/
+   
+   .ellipsis-toggle input:checked + .ellipsis {
+     display: none;
+   }
+   .ellipsis-toggle input:checked ~ .ellipsis-content {
+     display: inline;
+	 background-color: #ddd;
+   }
+   hr {
+    border: none;
+    height: 1px;
+    background-color: black;
+	margin: 0;
+   }
   </style>
  </head>
  <body>
@@ -1023,18 +1055,54 @@ var compStateMsg = `
   <div class="error">Error: <pre>{{.Error}}</pre></div>
  {{end}}
 
- <details>
+<details>
-  <summary>Gas Trace</summary>
+<summary>Gas Trace</summary>
-  <table>
+<table>
  <tr><th>Name</th><th>Total/Compute/Storage</th><th>Time Taken</th><th>Location</th></tr>
  {{range .GasCharges}}
-    <tr><td>{{.Name}}</td><td>{{.TotalGas}}/{{.ComputeGas}}/{{.StorageGas}}</td><td>{{.TimeTaken}}</td><td>{{.Location}}</td></tr>
+ <tr><td>{{.Name}}</td><td>{{.TotalGas}}/{{.ComputeGas}}/{{.StorageGas}}</td><td>{{.TimeTaken}}</td>
+  <td>
+   {{ $fImp := FirstImportant .Location }}
+   {{ if $fImp }}
+   <details>
+    <summary>{{ $fImp }}</summary><hr />
+	{{ $elipOn := false }}
+    {{ range $index, $ele := .Location -}}
+     {{- if $index }}<br />{{end -}}
+     {{- if .Show -}}
+	  {{ if $elipOn }}
+	   {{ $elipOn = false }}
+       </span></label>
+	  {{end}}
+
+      {{- if .Important }}<b>{{end -}}
+      {{- . -}}
+      {{if .Important }}</b>{{end}}
+     {{else}}
+	  {{ if not $elipOn }}
+	    {{ $elipOn = true }}
+        <label class="ellipsis-toggle"><input type="checkbox" /><span class="ellipsis">[…]<br /></span>
+		<span class="ellipsis-content">
+	  {{end}}
+      {{- "" -}}
+      {{- . -}}
+     {{end}}
+    {{end}}
+	{{ if $elipOn }}
+	  {{ $elipOn = false }}
+      </span></label>
+	{{end}}
+   </details>
+  {{end}}
+  </td></tr>
   {{end}}
   {{with SumGas .GasCharges}}
   <tr class="sum"><td><b>Sum</b></td><td>{{.TotalGas}}/{{.ComputeGas}}/{{.StorageGas}}</td><td>{{.TimeTaken}}</td><td></td></tr>
   {{end}}
-  </table>
+</table>
- </details>
+</details>
+
+
  {{if gt (len .Subcalls) 0}}
   <div>Subcalls:</div>
   {{$hash := .Hash}}
@@ -1062,6 +1130,17 @@ func computeStateHTMLTempl(ts *types.TipSet, o *api.ComputeStateOutput, getCode
 		"SumGas":     sumGas,
 		"CodeStr":    codeStr,
 		"Call":       call,
+		"FirstImportant": func(locs []types.Loc) *types.Loc {
+			if len(locs) != 0 {
+				for _, l := range locs {
+					if l.Important() {
+						return &l
+					}
+				}
+				return &locs[0]
+			}
+			return nil
+		},
 	}).Parse(compStateTemplate)
 	if err != nil {
 		return err