Concurrency support (#3)

README.md

@@ -24,8 +24,6 @@ Let's say you have a simple `main.go` file in the current working directory with
 ```go
 package main
 
-import "fmt"
-
 func test(i int, b bool) int {
 	if b {
 		return i
@@ -34,8 +32,7 @@ func test(i int, b bool) int {
 }
 
 func main() {
-	i := test(2, false)
-	fmt.Println(i)
+	_ = test(2, false)
 }
 ```
 
@@ -48,45 +45,87 @@ The file will be modified like the following:
 ```go
 package main
 
-import "fmt"
+import (
+	"crypto/rand"
+	"fmt"
+	rt "runtime"
+)
 
 func test(i int, b bool) int {
-	fmt.Printf("Entering function test with args (%v) (%v)\n", i, b)
-	defer fmt.Printf("Exiting function test\n")
+
+	/* prinTracer */
+	funcName := "test"
+	caller := "unknown"
+	if funcPC, _, _, ok := rt.Caller(0); ok {
+		funcName = rt.FuncForPC(funcPC).Name()
+	}
+	if callerPC, _, _, ok := rt.Caller(1); ok {
+		caller = rt.FuncForPC(callerPC).Name()
+	}
+	idBytes := make([]byte, 16)
+	_, _ = rand.Read(idBytes)
+	callID := fmt.Sprintf("%x-%x-%x-%x-%x", idBytes[0:4], idBytes[4:6], idBytes[6:8], idBytes[8:10], idBytes[10:])
+	fmt.Printf("Entering function %s called by %s with args (%v) (%v); callID=%s\n", funcName, caller, i, b, callID)
+	defer fmt.Printf("Exiting function %s called by %s; callID=%s\n", funcName, caller, callID) /* prinTracer */
+
 	if b {
 		return i
 	}
 	return 0
 }
 
 func main() {
-	fmt.Printf("Entering function main\n")
-	defer fmt.Printf("Exiting function main\n")
-	i := test(2, false)
-	fmt.Println(i)
+
+	/* prinTracer */
+	funcName := "main"
+	caller := "unknown"
+	if funcPC, _, _, ok := rt.Caller(0); ok {
+		funcName = rt.FuncForPC(funcPC).Name()
+	}
+	if callerPC, _, _, ok := rt.Caller(1); ok {
+		caller = rt.FuncForPC(callerPC).Name()
+	}
+	idBytes := make([]byte, 16)
+	_, _ = rand.Read(idBytes)
+	callID := fmt.Sprintf("%x-%x-%x-%x-%x", idBytes[0:4], idBytes[4:6], idBytes[6:8], idBytes[8:10], idBytes[10:])
+	fmt.Printf("Entering function %s called by %s; callID=%s\n", funcName, caller, callID)
+	defer fmt.Printf("Exiting function %s called by %s; callID=%s\n", funcName, caller, callID) /* prinTracer */
+
+	_ = test(2, false)
 }
 ```
+When running the instrumented file above the output (so called trace) will be as follows:
+```
+Entering function main.main called by runtime.main; callID=0308fc13-5b30-5871-9101-b84e055a9565
+Entering function main.test called by main.main with args (2) (false); callID=1a3feff5-844b-039c-6d20-307d52002ce8
+Exiting function main.test called by main.main; callID=1a3feff5-844b-039c-6d20-307d52002ce8
+Exiting function main.main called by runtime.main; callID=0308fc13-5b30-5871-9101-b84e055a9565
+```
 
 You can also easily revert all the changes done by `printracer` by just executing:
 ```
 printracer revert
 ```
 
+> NOTE: `printracer revert` reverts changes only if code block enclosed by /* prinTracer */ comments is not modified by hand. If you modify the instrumentation block then it should be manually reverted afterwards. 
+
+> NOTE: `printracer apply` will not apply any changes if find /* prinTracer */ comment directly above first statement in the function's body. This is needed to mitigate accidental multiple instrumentation which will then affect deinstrumentation and visualization negatively.
+You also can use it to signal that a particular function should not be instrumented.
 ### Visualization
 
 Let's say you have instrumented your code and captured the flow that is so hard to follow even the textual trace is confusing as hell.
 That's where visualization comes to rescue.
 
 For example let's say you have captured the following trace and saved it to the file **trace.txt**:
 ```text
-Entering function main
-Entering function foo with args (1) (true)
-Entering function bar with args (test string)
-Entering function baz
-Exiting function baz
-Exiting function bar
-Exiting function foo
-Exiting function main
+Entering function main.main called by runtime.main; callID=ec57b80b-6898-75cc-1dea-e623e7ac26c9
+Entering function main.foo called by main.main with args (5) (false); callID=351b3edb-7ad3-2f88-1a9b-488debf800cc
+Entering function main.bar called by main.foo with args (test string); callID=1e3e0e73-e4f1-b3f9-6bf5-e0aa15ddd6d1
+Entering function main.baz called by main.bar; callID=e1e79e3b-d89f-6e4e-e0bf-eea54db5b569
+Exiting function main.baz called by main.bar; callID=e1e79e3b-d89f-6e4e-e0bf-eea54db5b569
+Exiting function main.bar called by main.foo; callID=1e3e0e73-e4f1-b3f9-6bf5-e0aa15ddd6d1
+Exiting function main.foo called by main.main; callID=351b3edb-7ad3-2f88-1a9b-488debf800cc
+Exiting function main.main called by runtime.main; callID=ec57b80b-6898-75cc-1dea-e623e7ac26c9
 ``` 
 
 In practice this would be much more complicated but it is enough for the sake of demonstration.
@@ -108,9 +147,11 @@ That's where `--depth (-d)` and `--func (-f)` flags comes to rescue.
 - `--depth` flag controls how deep in the invocation graph you want your visualization to go.
 - `--func` flag controls which function to be the starting point of the visualization.
 
+> NOTE: If `--depth/--func` flags are used visualization will be linear following the call stack of the starting func. Calls from different Goroutines will be ignored!
+
 So if you execute the following command with the trace of the previous example:
 ```
-printracer visualize trace.txt --depth 2 --func foo
+printracer visualize trace.txt --depth 2 --func main.foo
 ```
 A diagram like this will be generated for you:
 

cmd/apply.go

@@ -41,6 +41,6 @@ func (ac *ApplyCmd) Run() error {
 		if err != nil {
 			return err
 		}
-		return ac.importsGroomer.RemoveUnusedImportFromDirectory(path, "fmt")
+		return ac.importsGroomer.RemoveUnusedImportFromDirectory(path, map[string]string{"fmt": "", "runtime": "rt", "rand": ""}) // TODO: flag for import aliases
 	})
 }

cmd/revert.go

@@ -41,6 +41,6 @@ func (rc *RevertCmd) Run() error {
 		if err != nil {
 			return err
 		}
-		return rc.importsGroomer.RemoveUnusedImportFromDirectory(path, "fmt")
+		return rc.importsGroomer.RemoveUnusedImportFromDirectory(path, map[string]string{"fmt": "", "runtime": "rt", "crypto/rand": ""}) // TODO: flag for import aliases
 	})
 }

cmd/visualize.go

@@ -39,8 +39,8 @@ func (vc *VisualizeCmd) Prepare() *cobra.Command {
 	}
 
 	result.Flags().StringVarP(&vc.outputFile, "output", "o", "calls", "name of the resulting html file when visualizing")
-	result.Flags().IntVarP(&vc.maxDepth, "depth", "d", math.MaxInt32, "maximum depth in call graph")
-	result.Flags().StringVarP(&vc.startingFunc, "func", "f", "", "name of the starting function in the visualization (the root of the diagram)")
+	result.Flags().IntVarP(&vc.maxDepth, "depth", "d", math.MaxInt32, "maximum depth in call graph. NOTE: If used visualization will be linear following the call stack of the starting func. Calls from different Goroutines will be ignored!")
+	result.Flags().StringVarP(&vc.startingFunc, "func", "f", "", "name of the starting function in the visualization (the root of the diagram). NOTE: If used visualization will be linear following the call stack of the starting func. Calls from different Goroutines will be ignored!")
 	return result
 }
 

parser/parser.go

@@ -19,24 +19,46 @@ const (
 )
 
 type FuncEvent interface {
-	FuncName() string
+	GetCaller() string
+	GetCallee() string
+	GetCallID() string
 }
 
 type InvocationEvent struct {
-	Name string
-	Args string
+	Caller string
+	Callee string
+	CallID string
+	Args   string
 }
 
-func (ie *InvocationEvent) FuncName() string {
-	return ie.Name
+func (ie *InvocationEvent) GetCaller() string {
+	return ie.Caller
+}
+
+func (ie *InvocationEvent) GetCallee() string {
+	return ie.Callee
+}
+
+func (ie *InvocationEvent) GetCallID() string {
+	return ie.CallID
 }
 
 type ReturningEvent struct {
-	Name string
+	Caller string
+	Callee string
+	CallID string
+}
+
+func (re *ReturningEvent) GetCaller() string {
+	return re.Caller
+}
+
+func (re *ReturningEvent) GetCallee() string {
+	return re.Callee
 }
 
-func (ie *ReturningEvent) FuncName() string {
-	return ie.Name
+func (re *ReturningEvent) GetCallID() string {
+	return re.CallID
 }
 
 type parser struct {
@@ -51,18 +73,26 @@ func (p *parser) Parse(in io.Reader) ([]FuncEvent, error) {
 	scanner := bufio.NewScanner(in)
 	for scanner.Scan() {
 		row := scanner.Text()
-		if strings.HasPrefix(row, "Entering function") {
-			words := strings.Split(row, " ")
+		lastSemicolon := strings.LastIndex(row, ";")
+		msg := row[:lastSemicolon]
+		secondHalf := row[lastSemicolon+1:]
+		callID := strings.Split(secondHalf, "=")[1]
+		if strings.HasPrefix(msg, "Entering function") {
+			words := strings.Split(msg, " ")
 			events = append(events, &InvocationEvent{
-				Name: words[2],
-				Args: strings.Join(words[3:], " "),
+				Callee: normalizeFuncName(words[2]),
+				Caller: normalizeFuncName(words[5]),
+				Args:   strings.Join(words[6:], " "),
+				CallID: callID,
 			})
 		}
 
-		if strings.HasPrefix(row, "Exiting function") {
-			split := strings.Split(row, " ")
+		if strings.HasPrefix(msg, "Exiting function") {
+			words := strings.Split(msg, " ")
 			events = append(events, &ReturningEvent{
-				Name: split[2],
+				Callee: normalizeFuncName(words[2]),
+				Caller: normalizeFuncName(words[5]),
+				CallID: callID,
 			})
 		}
 	}
@@ -72,3 +102,7 @@ func (p *parser) Parse(in io.Reader) ([]FuncEvent, error) {
 
 	return events, nil
 }
+
+func normalizeFuncName(funcName string) string {
+	return funcName[strings.LastIndex(funcName, "/")+1:]
+}

parser/parser_test.go

@@ -7,34 +7,58 @@ import (
 )
 
 func TestParser_Parse(t *testing.T) {
-	input := `Entering function main
-Entering function foo with args (1) (true)
-Entering function bar with args (test string)
-Entering function baz
-Exiting function baz
-Exiting function bar
-Exiting function foo
-Exiting function main`
+	input := `Entering function main.main called by runtime.main; callID=1d8ca74e-c860-8a75-fc36-fe6d34350f0c
+Entering function main.foo called by main.main with args (5) (false); callID=973355a9-2ec6-095c-9137-7a1081ac0a5f
+Entering function main.bar called by main.foo with args (test string); callID=6c294dfd-4c6a-39b1-474e-314bee73f514
+Entering function main.baz called by main.bar; callID=a019a297-0a6e-a792-0e3f-23c33a44622f
+Exiting function main.baz called by main.bar; callID=a019a297-0a6e-a792-0e3f-23c33a44622f
+Exiting function main.bar called by main.foo; callID=6c294dfd-4c6a-39b1-474e-314bee73f514
+Exiting function main.foo called by main.main; callID=973355a9-2ec6-095c-9137-7a1081ac0a5f
+Exiting function main.main called by runtime.main; callID=1d8ca74e-c860-8a75-fc36-fe6d34350f0c`
 
 	expected := []FuncEvent{
 		&InvocationEvent{
-			Name: "main",
+			Caller: "runtime.main",
+			Callee: "main.main",
+			CallID: "1d8ca74e-c860-8a75-fc36-fe6d34350f0c",
 		},
 		&InvocationEvent{
-			Name: "foo",
-			Args: "with args (1) (true)",
+			Caller: "main.main",
+			Callee: "main.foo",
+			CallID: "973355a9-2ec6-095c-9137-7a1081ac0a5f",
+			Args:   "with args (5) (false)",
 		},
 		&InvocationEvent{
-			Name: "bar",
-			Args: "with args (test string)",
+			Caller: "main.foo",
+			Callee: "main.bar",
+			CallID: "6c294dfd-4c6a-39b1-474e-314bee73f514",
+			Args:   "with args (test string)",
 		},
 		&InvocationEvent{
-			Name: "baz",
+			Caller: "main.bar",
+			Callee: "main.baz",
+			CallID: "a019a297-0a6e-a792-0e3f-23c33a44622f",
+		},
+		&ReturningEvent{
+			Caller: "main.bar",
+			Callee: "main.baz",
+			CallID: "a019a297-0a6e-a792-0e3f-23c33a44622f",
+		},
+		&ReturningEvent{
+			Caller: "main.foo",
+			Callee: "main.bar",
+			CallID: "6c294dfd-4c6a-39b1-474e-314bee73f514",
+		},
+		&ReturningEvent{
+			Caller: "main.main",
+			Callee: "main.foo",
+			CallID: "973355a9-2ec6-095c-9137-7a1081ac0a5f",
+		},
+		&ReturningEvent{
+			Caller: "runtime.main",
+			Callee: "main.main",
+			CallID: "1d8ca74e-c860-8a75-fc36-fe6d34350f0c",
 		},
-		&ReturningEvent{Name: "baz"},
-		&ReturningEvent{Name: "bar"},
-		&ReturningEvent{Name: "foo"},
-		&ReturningEvent{Name: "main"},
 	}
 
 	actual, err := NewParser().Parse(bytes.NewBufferString(input))