diff --git a/Documentation/usage/dlv_trace.md b/Documentation/usage/dlv_trace.md index d4d16b2528..be2d383c38 100644 --- a/Documentation/usage/dlv_trace.md +++ b/Documentation/usage/dlv_trace.md @@ -23,7 +23,7 @@ dlv trace [package] regexp [flags] ``` --ebpf Trace using eBPF (experimental). -e, --exec string Binary file to exec and trace. - --follow-calls int Trace all children of the function to the required depth + --follow-calls int Trace all children of the function to the required depth. Trace also supports defer functions and cases where functions are dynamically returned and passed as parameters. -h, --help help for trace --output string Output path for the binary. -p, --pid int Pid to attach to. diff --git a/_fixtures/testtracefns.go b/_fixtures/testtracefns.go index 84c6f3b74d..a40c396b0c 100644 --- a/_fixtures/testtracefns.go +++ b/_fixtures/testtracefns.go @@ -69,6 +69,75 @@ func F4() { panic("blah") } +var intc, intd int + +func swap() { + defer func() { + intc += 100 + }() + temp := intc + intc = intd + intd = temp +} + +func unnamedDefer() { + intc = -100 + intd = 100 + swap() + fmt.Println(intc, intd) +} +func formula(op string) func(int, int) int { + var calc func(int, int) int + if op == "add" { + calc = func(m int, n int) int { + res := m + n + return res + } + } else if op == "mul" { + calc = func(m int, n int) int { + res := m * n + return res + } + } + return calc +} + +func op() int { + calc := formula("add") + res := calc(10, 20) + return res +} + +func assign(bar func()) { + bar() +} +func testfunc() { + intc = 10 + intd = 20 +} + +func dyn() { + intc = 0 + intd = 0 + assign(testfunc) +} + +func outer() { + intc = 40 + defer swap() +} +func nestDefer() { + defer outer() +} + +func namedDeferLoop(n int) { + for i := 0; i < n; i++ { + defer testfunc() + } + temp := intc + intc = intd + intd = temp +} func main() { j := 0 j += A(2) @@ -76,6 +145,12 @@ func main() { j += first(6) j += callme(2) fmt.Println(j) + unnamedDefer() + nestDefer() + namedDeferLoop(2) F0() + ans := op() + fmt.Println(ans) + dyn() } diff --git a/cmd/dlv/cmds/commands.go b/cmd/dlv/cmds/commands.go index 054623f483..3f7406593d 100644 --- a/cmd/dlv/cmds/commands.go +++ b/cmd/dlv/cmds/commands.go @@ -369,7 +369,7 @@ only see the output of the trace operations you can redirect stdout.`, must(traceCommand.RegisterFlagCompletionFunc("stack", cobra.NoFileCompletions)) traceCommand.Flags().String("output", "", "Output path for the binary.") must(traceCommand.MarkFlagFilename("output")) - traceCommand.Flags().IntVarP(&traceFollowCalls, "follow-calls", "", 0, "Trace all children of the function to the required depth") + traceCommand.Flags().IntVarP(&traceFollowCalls, "follow-calls", "", 0, "Trace all children of the function to the required depth. Trace also supports defer functions and cases where functions are dynamically returned and passed as parameters.") rootCommand.AddCommand(traceCommand) coreCommand := &cobra.Command{ diff --git a/pkg/proc/breakpoints.go b/pkg/proc/breakpoints.go index 5800d65c07..8b508198c4 100644 --- a/pkg/proc/breakpoints.go +++ b/pkg/proc/breakpoints.go @@ -113,6 +113,11 @@ type Breaklet struct { watchpoint *Breakpoint } +// SetCallback sets the call back field, this was primarily added to prevent exporting callback field +func (b *Breaklet) SetCallback(callback func(th Thread, p *Target) (bool, error)) { + b.callback = callback +} + // BreakpointKind determines the behavior of delve when the // breakpoint is reached. type BreakpointKind uint16 diff --git a/service/debugger/debugger.go b/service/debugger/debugger.go index bc3559fcaf..5f0d60c570 100644 --- a/service/debugger/debugger.go +++ b/service/debugger/debugger.go @@ -409,13 +409,10 @@ func (d *Debugger) LastModified() time.Time { return d.target.Selected.BinInfo().LastModified() } -// FunctionReturnLocations returns all return locations -// for the given function, a list of addresses corresponding -// to 'ret' or 'call runtime.deferreturn'. -func (d *Debugger) FunctionReturnLocations(fnName string) ([]uint64, error) { - d.targetMutex.Lock() - defer d.targetMutex.Unlock() - +// functionReturnLocationsInternal is same as FunctionReturnLocations +// except that it does not have a lock and unlock as its called from +// within the callback which has already acquired a lock. +func (d *Debugger) functionReturnLocationsInternal(fnName string) ([]uint64, error) { if len(d.target.Targets()) > 1 { return nil, ErrNotImplementedWithMultitarget } @@ -454,6 +451,15 @@ func (d *Debugger) FunctionReturnLocations(fnName string) ([]uint64, error) { return addrs, nil } +// FunctionReturnLocations returns all return locations +// for the given function, a list of addresses corresponding +// to 'ret' or 'call runtime.deferreturn'. +func (d *Debugger) FunctionReturnLocations(fnName string) ([]uint64, error) { + d.targetMutex.Lock() + defer d.targetMutex.Unlock() + return d.functionReturnLocationsInternal(fnName) +} + // Detach detaches from the target process. // If `kill` is true we will kill the process after // detaching. @@ -1372,7 +1378,7 @@ func (d *Debugger) Functions(filter string, followCalls int) ([]string, error) { for _, f := range t.BinInfo().Functions { if regex.MatchString(f.Name) { if followCalls > 0 { - newfuncs, err := traverse(t, &f, 1, followCalls) + newfuncs, err := d.traverse(t, &f, 1, followCalls, filter) if err != nil { return nil, fmt.Errorf("traverse failed with error %w", err) } @@ -1388,12 +1394,13 @@ func (d *Debugger) Functions(filter string, followCalls int) ([]string, error) { return funcs, nil } -func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int) ([]string, error) { +func (d *Debugger) traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int, rootstr string) ([]string, error) { type TraceFunc struct { Func *proc.Function Depth int visited bool } + type TraceFuncptr *TraceFunc TraceMap := make(map[string]TraceFuncptr) @@ -1409,7 +1416,7 @@ func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int) parent := queue[0] queue = queue[1:] if parent == nil { - panic("attempting to open file Delve cannot parse") + panic("queue has a nil node, cannot traverse!") } if parent.Depth > followCalls { continue @@ -1427,10 +1434,89 @@ func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int) } f := parent.Func text, err := proc.Disassemble(t.Memory(), nil, t.Breakpoints(), t.BinInfo(), f.Entry, f.End) + if err != nil { return nil, fmt.Errorf("disassemble failed with error %w", err) } for _, instr := range text { + // Dynamic functions need to be handled specially as their destination location + // is not known statically, hence its required to put a breakpoint in order to + // acquire the address of the function at runtime and we do this via a + // call back mechanism + if instr.IsCall() && instr.DestLoc == nil { + dynbp, err := t.SetBreakpoint(0, instr.Loc.PC, proc.NextBreakpoint, nil) + if err != nil { + return nil, fmt.Errorf("error setting breakpoint inside deferreturn") + } + dynCallback := func(th proc.Thread, tgt *proc.Target) (bool, error) { + // TODO(optimization): Consider using an iterator to avoid materializing + // the full stack when we only need frames up to the root function + rawlocs, err := proc.ThreadStacktrace(tgt, tgt.CurrentThread(), followCalls+2) + if err != nil { + return false, fmt.Errorf("thread stack trace returned error") + } + // Since the dynamic function is known only at runtime, the depth is likewise + // calculated by referring to the stack and the mechanism is similar to that + // used in pkg/terminal/command.go:printTraceOutput + rootindex := -1 + for i := len(rawlocs) - 1; i >= 0; i-- { + if rawlocs[i].Call.Fn.Name == rootstr { + if rootindex == -1 { + rootindex = i + break + } + } + } + sdepth := rootindex + 1 + + if sdepth+1 > followCalls { + return false, nil + } + regs, err := th.Registers() + if err != nil { + return false, fmt.Errorf("registers inside callback returned err") + + } + // Disassemble the instruction at the current PC to get the call destination + pc := instr.Loc.PC + maxInstLen := uint64(tgt.BinInfo().Arch.MaxInstructionLength()) + disasm, err := proc.Disassemble(t.Memory(), regs, t.Breakpoints(), tgt.BinInfo(), pc, pc+maxInstLen) + if err != nil { + return false, fmt.Errorf("failed to disassemble instruction: %w", err) + } + + // Extract address from the decoded instruction's destination location + var addr uint64 + if len(disasm) > 0 && disasm[0].DestLoc != nil { + addr = disasm[0].DestLoc.PC + } else { + return false, fmt.Errorf("failed to extract call destination from instruction at PC %#x", pc) + } + fn := tgt.BinInfo().PCToFunc(addr) + if fn == nil { + return false, fmt.Errorf("PCToFunc returned nil") + } + err = createFunctionTracepoints(d, fn.Name, rootstr, followCalls) + if err != nil { + return false, fmt.Errorf("error creating tracepoint in function %s", fn.Name) + } + dynchildren, err := d.traverse(t, fn, sdepth+1, followCalls, rootstr) + if err != nil { + return false, fmt.Errorf("error calling traverse on dynamic children") + } + for _, child := range dynchildren { + err := createFunctionTracepoints(d, child, rootstr, followCalls) + if err != nil { + return false, fmt.Errorf("error creating tracepoint in function %s", child) + } + } + return false, nil + } + for _, dynBrklet := range dynbp.Breaklets { + dynBrklet.SetCallback(dynCallback) + } + } + if instr.IsCall() && instr.DestLoc != nil && instr.DestLoc.Fn != nil { cf := instr.DestLoc.Fn if (strings.HasPrefix(cf.Name, "runtime.") || strings.HasPrefix(cf.Name, "runtime/internal")) && cf.Name != "runtime.deferreturn" && cf.Name != "runtime.gorecover" && cf.Name != "runtime.gopanic" { @@ -1449,6 +1535,70 @@ func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int) return funcs, nil } +// createFunctionTracepoints is a way to create a trace point late in the cycle but just in time that +// it can be included in the trace output as in the case of dynamic functions, we get to know the +// functions that are being called from deferreturn quite late in execution. This might create multiple +// tracepoints +func createFunctionTracepoints(d *Debugger, fname string, rootstr string, followCalls int) error { + + // Helper function to create breakpoints for tracepoints + // Ignore BreakpointExistsError since duplicate tracepoints + // are expected during dynamic function discovery + createBrkForTracepoint := func(lbp *proc.LogicalBreakpoint) error { + d.breakpointIDCounter++ + lbp.LogicalID = d.breakpointIDCounter + lbp.HitCount = make(map[int64]uint64) + d.target.LogicalBreakpoints[lbp.LogicalID] = lbp + err := d.target.SetBreakpointEnabled(lbp, true) + if err != nil { + delete(d.target.LogicalBreakpoints, lbp.LogicalID) + // Silently ignore BreakpointExistsError - this is expected when + // creating tracepoints for functions that may already have them + if _, exists := err.(proc.BreakpointExistsError); exists { + return nil + } + return err + } + return nil + } + + // Create tracepoint for function entry + lbp := &proc.LogicalBreakpoint{ + Set: proc.SetBreakpoint{ + FunctionName: fname, + }, + Tracepoint: true, + RootFuncName: rootstr, + Stacktrace: 20, + TraceFollowCalls: followCalls, + } + + err := createBrkForTracepoint(lbp) + if err != nil { + return fmt.Errorf("error creating breakpoint at function %s: %w", fname, err) + } + + // Create tracepoints for function return locations + raddrs, _ := d.functionReturnLocationsInternal(fname) + for i := range raddrs { + retLbp := &proc.LogicalBreakpoint{ + Set: proc.SetBreakpoint{ + PidAddrs: []proc.PidAddr{{Pid: d.target.Selected.Pid(), Addr: raddrs[i]}}, + }, + TraceReturn: true, + RootFuncName: rootstr, + Stacktrace: 20, + TraceFollowCalls: followCalls, + } + + err := createBrkForTracepoint(retLbp) + if err != nil { + return fmt.Errorf("error creating breakpoint at function return %s: %w", fname, err) + } + } + return nil +} + // Types returns all type information in the binary. func (d *Debugger) Types(filter string) ([]string, error) { d.targetMutex.Lock() diff --git a/service/test/integration2_test.go b/service/test/integration2_test.go index bfe1232232..a1fa754504 100644 --- a/service/test/integration2_test.go +++ b/service/test/integration2_test.go @@ -806,28 +806,65 @@ func matchFunctions(t *testing.T, funcs []string, expected []string, depth int) func TestTraceFollowCallsCommand(t *testing.T) { protest.AllowRecording(t) withTestClient2("testtracefns", t, func(c service.Client) { - depth := 3 - functions, err := c.ListFunctions("main.A", depth) - assertNoError(err, t, "ListFunctions()") - expected := []string{"main.A", "main.B", "main.C", "main.D"} - matchFunctions(t, functions, expected, depth) - - functions, err = c.ListFunctions("main.first", depth) - assertNoError(err, t, "ListFunctions()") - expected = []string{"main.first", "main.second"} - matchFunctions(t, functions, expected, depth) - - depth = 4 - functions, err = c.ListFunctions("main.callme", depth) - assertNoError(err, t, "ListFunctions()") - expected = []string{"main.callme", "main.callme2", "main.callmed", "main.callmee"} - matchFunctions(t, functions, expected, depth) - - depth = 6 - functions, err = c.ListFunctions("main.F0", depth) - assertNoError(err, t, "ListFunctions()") - expected = []string{"main.F0", "main.F0.func1", "main.F1", "main.F2", "main.F3", "main.F4", "runtime.deferreturn", "runtime.gopanic", "runtime.gorecover"} - matchFunctions(t, functions, expected, depth) + testCases := []struct { + funcName string + depth int + expected []string + }{ + { + funcName: "main.A", + depth: 3, + expected: []string{"main.A", "main.B", "main.C", "main.D"}, + }, + { + funcName: "main.first", + depth: 3, + expected: []string{"main.first", "main.second"}, + }, + { + funcName: "main.callme", + depth: 4, + expected: []string{"main.callme", "main.callme2", "main.callmed", "main.callmee"}, + }, + { + funcName: "main.F0", + depth: 6, + expected: []string{"main.F0", "main.F0.func1", "main.F1", "main.F2", "main.F3", "main.F4", "runtime.deferreturn", "runtime.gopanic", "runtime.gorecover"}, + }, + { + funcName: "main.swap", + depth: 3, + expected: []string{"main.swap", "main.swap.func1", "runtime.deferreturn"}, + }, + { + funcName: "main.nestDefer", + depth: 7, + expected: []string{"main.nestDefer", "runtime.deferreturn", "main.outer", "main.swap", "main.swap.func1"}, + }, + { + funcName: "main.namedDeferLoop", + depth: 3, + expected: []string{"main.namedDeferLoop", "runtime.deferreturn", "main.testfunc"}, + }, + { + funcName: "main.op", + depth: 3, + expected: []string{"main.formula", "main.op", "main.formula.func1"}, + }, + { + funcName: "main.dyn", + depth: 3, + expected: []string{"main.assign", "main.dyn", "main.testfunc"}, + }, + } + + for _, tc := range testCases { + t.Run(tc.funcName, func(t *testing.T) { + functions, err := c.ListFunctions(tc.funcName, tc.depth) + assertNoError(err, t, "ListFunctions()") + matchFunctions(t, functions, tc.expected, tc.depth) + }) + } }) }