Support to add a new suboption --follow-calls to trace subcommand

[archanaravindar]

Support for an option to the trace subcommand, "--follow-calls " which traverses the children of the functions being traced upto the desired depth
specified by the user.
n=0 is the same as the plain trace subcommand
n=1 is print the trace of functions at level=1 which is again equivalent to the plain trace subcommand
n=2 is print the trace of functions at level=2 which prints the immediate child of the function being traced along with the function
n=3 is print the trace of functions at level=3 which prints the function being traced along with two levels of children down the call tree
and so on..

This option also indents the output according to depth for the calls occurring in the program
Calls such as runtime.morestack_noctxt are treated specially and do not adhere to the definition of depth like the other functions
Though we can also trace morestack_noctxt calls if desired

For example, if we have a simple .go program such as the following

package main
import "fmt"
func D(i int) int {
        return i*i*i
}
func C(i int) int {

        return i+20
}
func B(i int) int {
        d:=C(i)+40
        return d+D(i)
}
func A(i int) int {
        return 10+B(i)
}
func main() {
        j := 0
        j += A(2)
        fmt.Println(j)
}

building leaf4 and running delve as follows would
give the following trace output

go build -gcflags '-N -l' ./leaf4.go 


../dlv trace main.A --follow-calls 3 -e=./leaf4^M
> goroutine(1): runtime.morestack_noctxt()^M
> goroutine(1): main.A(2)^M
 > goroutine(1): main.B(2)^M
  > goroutine(1): main.C(2)^M
  >> goroutine(1): => (22)^M
  > goroutine(1): main.D(2)^M
  >> goroutine(1): => (8)^M
 >> goroutine(1): => (70)^M
>> goroutine(1): => (80)^M
> goroutine(1): runtime.morestack_noctxt()^M
80^M

[aarzilli]

I think it would be better to just have one of these end to end tests and then test the rest of the detailis in service/test/integration2_test.go by just calling ListFunctions directly.

[aarzilli]

You should keep track of which functions have been visited already and avoid revisiting them.

[archanaravindar]

Hi Alessandro for functions which have a call graph pattern such as the following example we need to be able to print out D twice once from B and once from C hence we kept only the check for recursion

package main
import "fmt"
func D(i int) int {
        return i*i*i
}
func C(i int) int {

        return D(i+10)+20
}
func B(i int) int {
        return i*D(i)
}
func A(i int) int {
        d:= 10+B(i)
        return d+C(i)
}
func main() {
        j := 0
        j += A(2)
        fmt.Println(j)
}

../dlv trace main.A --follow-calls 3 -e=./leafcommon
> goroutine(1): runtime.morestack_noctxt()
> goroutine(1): runtime.morestack_noctxt()
> goroutine(1): main.A(2)
 > goroutine(1): main.B(2)
  > goroutine(1): main.D(2)
  >> goroutine(1): => (8)
 >> goroutine(1): => (16)
> goroutine(1): runtime.morestack_noctxt()
 > goroutine(1): main.C(2)
  > goroutine(1): main.D(12)
  >> goroutine(1): => (1728)
 >> goroutine(1): => (1748)
>> goroutine(1): => (1774)
> goroutine(1): runtime.morestack_noctxt()
1774

[aarzilli]

Sure, but you can't set more than one breakpoint on D.

[derekparker]

I agree here. We could have a map like visited map[string]struct{}{} so that if we've already traversed a function, we don't waste time doing it again. Eventually those results will be removed by uniq later, but it's best to not even waste time going through that call graph again.

[archanaravindar]

After some discussion with @derekparker we realized that we may end up going further down the call graph of the function depending on how we got to it and how far down in depth we are... so there can be a situation we may miss on a child if we short circuit the traversal
alternatively looking at it, we can come to a function from two different parents and we would then need to traverse such a function twice anyway

[aarzilli]

After some discussion with @derekparker we realized that we may end up going further down the call graph of the function depending on how we got to it and how far down in depth we are

True, let's make this a breadth first visit instead.

[aarzilli]

Just to stress why this is important: tracing a function that calls fmt.Printf with --follow-calls=10 on my system takes 10 seconds, just to set up the breakpoints. The number of breakpoints it ends up setting is relatively small (222) but to do that it ends up disassembly the same functions thousands of times. For example fmt.(*buffer).writeString is visited by traverse 4727 times (and redisassembled each time), runtime.panicIndex is visited 7900 times.

This implementation is extremely inefficient.

[derekparker]

I agree here. We could have a map like visited map[string]struct{}{} so that if we've already traversed a function, we don't waste time doing it again. Eventually those results will be removed by uniq later, but it's best to not even waste time going through that call graph again.

[aarzilli]

I don't understand what this is doing. Shouldn't you be counting all appearances of traced calls in the stack?

[aarzilli]

After some discussion with @derekparker we realized that we may end up going further down the call graph of the function depending on how we got to it and how far down in depth we are

True, let's make this a breadth first visit instead.

[aarzilli]

Can you explain what the logic behind this calculation is? Why is wantindex even needed? Why are you calculating curi as len(stack) - 1 - i when you later use it in a way that will always cancel the len(stack) term?

[archanaravindar]

There were many reasons for this- we needed rootindex to mark the depth of the starting func name as without that, it would report depth relative to main and not the function which was being given as a parameter, calculating it as len(stack)-1-i helps us to traverse from bottom up so that we can set rootindex properly at the first match in case the same function gets recursively invoked later (to avoid overwriting it with a higher depth etc), wantindex was required to mark depth of the function corresponding to the tracepoint.

[aarzilli]

Right, but why is wantindex the deepest call of the current tracepoint function and rootindex the least deep call? What if the current tracepoint function is recursively calling itself? Should that not increment the depth? What if the deepest call of the current tracepoint function is deeper than the least deep call of the root function?

[archanaravindar]

Hi Alessandro, the way the stack is traversed being bottom up - it appears that rootindex is the least deep call because we are consider depth by subtracting off len(stack), hence when we are computing depth we do it by subtracting the index of the traced function from the root index. if a function calls itself the depth is incremented automatically by the curi being reassigned to curi based on the match in every iteration.
I have tested it for both direct and indirect recursion for instance if A calls itself we get an output trace like this-

./dlv trace main.A --follow-calls 3 -e=./leafrec
1> goroutine(1): main.A(5, 5)^M
 2> goroutine(1): main.A(4, 4)^M
  3> goroutine(1): main.A(3, 3)^M
  3>> goroutine(1):(main.A) => (6)^M 
 2>> goroutine(1):(main.A) => (24)^M
1>> goroutine(1):(main.A) => (120)^M

This is the qstn i did not understand? What if the deepest call of the current tracepoint function is deeper than the least deep call of the root function? can you give me an example?

[aarzilli]

To be honest I undestand what this code is trying to do so little that I can't really tell what's intended behavior and what's a bug.

[aarzilli]

Just to stress why this is important: tracing a function that calls fmt.Printf with --follow-calls=10 on my system takes 10 seconds, just to set up the breakpoints. The number of breakpoints it ends up setting is relatively small (222) but to do that it ends up disassembly the same functions thousands of times. For example fmt.(*buffer).writeString is visited by traverse 4727 times (and redisassembled each time), runtime.panicIndex is visited 7900 times.

This implementation is extremely inefficient.

[archanaravindar]

Hi @aarzilli thanks for your suggestion to improve the performance of the traversal algorithm, we are working on this now, can you please give the same example as mentioned in #3594 (comment)
you had seen which was very inefficient so that we could try it with the new implementation and see if we got improvement, thanks!

[aarzilli]

can you please give the same example as mentioned in #3594 (comment)

Just:

package main

import "fmt"

func f() {
    fmt.Printf("hello world\n")
}

func main() {
    f()
}

and trace main.f with --follow-calls=10, if that's fast for you try --follow-calls=10000.

[archanaravindar]

Optimized traversal and tested with example provided in #3594 (comment)
Testing with depth of 10000 the execution time remains well below 1 second

[aarzilli]

Optimized traversal

I think that making it a BFS is still preferable to optimizing a DFS with caching:

d := make(map[string]int)
fringe := []string
add := func(fname string, dist int) {
	if curdist, ok := d[fname]; ok {
		if curdist > dist {
			d[fname] = dist
		}
		return
	}
	d[fname] = dist
	fringe = append(fringe, fname)
}

add(f.Name)

for len(fringe) > 0 {
	cur = fringe[0]
	fringe = fringe[1:] // leaking slightly but it should be fine
	if d[cur] >= depth {
		continue
	}
	dcur := d[cur]
	for _, next := range functionsCalledFromDisassembly(cur) {
		add(next, dcur+1)
	}
}

r := []string{}
for fname, dist := range d {
	if dist < depth {
		r = append(r, fname)
	}
}
return r

(not tested, didn't even compile it)

[archanaravindar]

Optimized traversal

I think that making it a BFS is still preferable to optimizing a DFS with caching:

Hi @aarzilli if there are no major performance issues in the DFS code u see, can we go ahead and merge this code and later do a performance enhancement ? @derekparker

[aarzilli]

The problem is not the performance, is that all these optimizations are unreadable and using the correct algorithm would render them unnecessary. Also, there are other comments on this code that have not been addressed in addition to traverse using the wrong algorithm, before we should merge this.

[derekparker]

Looks good, I like the BFS approach, but I think due to using BFS we can simplify and clean this up even more.