perf(indexer): share the call graph of the index, log no line per call

docs/projectgraph.md

@@ -106,6 +106,13 @@ version. On the next run the store serves the artifact and the plugin gets
 it through `Restore` with no parse. A new plugin version misses every older
 artifact. `Prune` removes artifacts as it removes indexes.
 
+A cached plugin that reads the call graph of a file implements
+`indexer.GraphPlugin`. The run builds the call graph once for the index, and
+gives it to `AnalyzeGraph` with the tree. The plugin does not build the graph
+again. The extra plugins run on one goroutine, so a second build would slow
+the whole run. A file that the workers finished before the deadline passed
+gets its full graph. With a done context, `Analyze` would build none.
+
 ## Link
 
 ```go

plugin/callgraph/context_test.go

@@ -12,6 +12,7 @@ import (
 	"github.com/safedep/code/parser"
 	"github.com/safedep/code/pkg/test"
 	"github.com/safedep/code/plugin"
+	"github.com/safedep/dry/log"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -119,3 +120,72 @@ func TestDoneContextStopsBuildCallGraphAtTheImports(t *testing.T) {
 	_, err = Build(ctx, tree)
 	assert.ErrorIs(t, err, context.Canceled)
 }
+
+func TestAnalyzeGraphFailsOnAPartialGraphAsAnalyzeTreeDoes(t *testing.T) {
+	python, err := lang.NewPythonLanguage()
+	require.NoError(t, err)
+	tree, err := parser.ParseBytes(t.Context(), python, []byte(deadlineSource), parser.WithFileName("calls.py"))
+	require.NoError(t, err)
+	defer tree.Close()
+	imports, err := python.Resolvers().ResolveImports(t.Context(), tree)
+	require.NoError(t, err)
+	treeData, err := tree.Data()
+	require.NoError(t, err)
+	partial := newCallGraph("calls.py", python.Meta().Code)
+	partial.build(&nodeDeadline{Context: t.Context(), graph: partial, nodes: 2 * ctxCheckInterval}, tree.Tree().RootNode(), imports, *treeData)
+	full, err := Build(t.Context(), tree)
+	require.NoError(t, err)
+
+	var got []*CallGraph
+	pl := NewCallGraphPlugin(func(_ context.Context, cg *CallGraph) error {
+		got = append(got, cg)
+		return nil
+	})
+	require.NoError(t, pl.AnalyzeGraph(t.Context(), full))
+	err = pl.AnalyzeGraph(t.Context(), partial)
+	assert.ErrorIs(t, err, context.DeadlineExceeded)
+	assert.Equal(t, []*CallGraph{full, partial}, got, "the callback gets the graph of the caller, the partial one too")
+}
+
+// A debug line for each call made the debug log of a large project run to
+// hundreds of thousands of lines. The log of a build must not grow with
+// the number of calls.
+func TestBuildLogsNoLineForEachCall(t *testing.T) {
+	for _, tc := range []struct {
+		name     string
+		language func() (core.Language, error)
+		file     string
+		source   func(calls int) string
+	}{
+		{"go", func() (core.Language, error) { return lang.NewGoLanguage() }, "main.go", func(n int) string {
+			return "package main\n\nfunc f() {}\n\nfunc g() {}\n\nfunc main() {\n" + strings.Repeat("\tf()\n", n) + "}\n"
+		}},
+		{"javascript", func() (core.Language, error) { return lang.NewJavascriptLanguage() }, "main.js", func(n int) string {
+			return "function f() {}\nconst g = () => {};\n" + strings.Repeat("f();\nnew Map();\n", n)
+		}},
+		{"python", func() (core.Language, error) { return lang.NewPythonLanguage() }, "main.py", func(n int) string {
+			return "class C:\n    pass\n\ndef f():\n    pass\n\n" + strings.Repeat("f()\nC()\n", n)
+		}},
+		{"java", func() (core.Language, error) { return lang.NewJavaLanguage() }, "Main.java", func(n int) string {
+			return "class Main {\n  void f() {}\n  void m() {\n" + strings.Repeat("    f();\n    new Main();\n    this.f();\n", n) + "  }\n}\n"
+		}},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			language, err := tc.language()
+			require.NoError(t, err)
+			lines := func(calls int) int {
+				tree, err := parser.ParseBytes(t.Context(), language, []byte(tc.source(calls)), parser.WithFileName(tc.file))
+				require.NoError(t, err)
+				defer tree.Close()
+				var buf strings.Builder
+				restore := log.SwapGlobalForTest(&buf)
+				defer restore()
+				cg, err := Build(t.Context(), tree)
+				require.NoError(t, err)
+				require.NotEmpty(t, cg.Nodes)
+				return strings.Count(buf.String(), "\n")
+			}
+			assert.Equal(t, lines(1), lines(50))
+		})
+	}
+}

plugin/callgraph/golang.go

@@ -106,7 +106,6 @@ func goCallExpressionProcessor(callNode *sitter.Node, treeData []byte, currentNa
 		ref := callGraph.reference(callee, CallCall, functionNode, callArguments)
 		ref.Unbound = unbound
 		callGraph.addCall(currentNamespace, nil, ref)
-		log.Debugf("Go call: %s -> %s", currentNamespace, callee)
 	}
 
 	return result
@@ -279,9 +278,7 @@ func goMethodDeclarationProcessor(methodDefNode *sitter.Node, treeData []byte, c
 		methodNamespace = currentNamespace + namespaceSeparator + receiverType + namespaceSeparator + methodName
 	}
 
-	if callGraph.addDefinition(methodNamespace, methodDefNode) {
-		log.Debugf("Register Go method definition for %s on %s - %s", methodName, receiverType, methodNamespace)
-	}
+	callGraph.addDefinition(methodNamespace, methodDefNode)
 	return processFunctionBody(methodDefNode, treeData, methodNamespace, callGraph, metadata)
 }
 

plugin/callgraph/java.go

@@ -222,8 +222,6 @@ func objectCreationExpressionProcessor(objectCreationNode *sitter.Node, treeData
 
 		classNode, classResolvedBySearch := searchSymbolInScopeChain(constructedClassName, currentNamespace, callGraph)
 		if classResolvedBySearch {
-			log.Debugf("Constructor %s searched (direct) & resolved to %s\n", constructedClassName, classNode.Namespace)
-
 			callGraph.addEdge(currentNamespace, CallNew, constructedClassNode, classNode.Namespace, nil, argsResult)
 			markClassAssignment(classNode)
 		} else if constructedClassNode.Type() == "scoped_type_identifier" {
@@ -289,7 +287,6 @@ func methodInvocationProcessor(methodInvocationNode *sitter.Node, treeData []byt
 
 	functionAssignmentNode, functionResolvedBySearch := searchSymbolInScopeChain(methodName, currentNamespace, callGraph)
 	if functionResolvedBySearch {
-		log.Debugf("Method invocation %s searched (direct) & resolved to %s\n", methodName, functionAssignmentNode.Namespace)
 		callGraph.addEdge(
 			currentNamespace, CallCall, methodInvocationNode,
 			functionAssignmentNode.Namespace, nil,
@@ -341,7 +338,6 @@ func resolveQualifiedInvocation(invocation, object *sitter.Node, methodName stri
 		if !chained {
 			callee = receiver + namespaceSeparator + methodName
 		}
-		log.Debugf("Method invocation %s searched (object qualified) & resolved to - %s\n", methodName, callee)
 		callGraph.addEdge(currentNamespace, CallCall, invocation, callee, nil, args)
 	}
 }

plugin/callgraph/javascript.go

@@ -209,7 +209,6 @@ func jsCallExpressionProcessor(callNode *sitter.Node, treeData []byte, currentNa
 		ref := callGraph.reference(callee, kind, functionNode, callArguments)
 		ref.Unbound = unbound
 		callGraph.addCall(currentNamespace, nil, ref)
-		log.Debugf("JS call: %s -> %s", currentNamespace, callee)
 		// The file cannot tell a factory of a dependency from a function of
 		// it. The value of the call is the callee, as for new X(), so
 		// app.get() in const app = express() keeps the import, as Python
@@ -463,9 +462,7 @@ func arrowFunctionProcessor(arrowNode *sitter.Node, treeData []byte, currentName
 	if functionName != "" {
 		arrowFunctionNamespace = currentNamespace + namespaceSeparator + functionName
 
-		if callGraph.addDefinition(arrowFunctionNamespace, arrowNode) {
-			log.Debugf("Register arrow function definition for %s - %s", functionName, arrowFunctionNamespace)
-		}
+		callGraph.addDefinition(arrowFunctionNamespace, arrowNode)
 	}
 
 	results.addResults(processFunctionBody(arrowNode, treeData, arrowFunctionNamespace, callGraph, metadata))
@@ -652,8 +649,6 @@ func jsNewExpressionProcessor(newNode *sitter.Node, treeData []byte, currentName
 	}
 
 	for _, constructor := range constructors {
-		log.Debugf("JS constructor resolved to %s", constructor)
-
 		ref := callGraph.reference(constructor, CallNew, constructorNode, callArguments)
 		ref.Unbound = unbound
 		callGraph.addCall(currentNamespace, nil, ref)

plugin/callgraph/plugin.go

@@ -37,7 +37,13 @@ func (p *callgraphPlugin) AnalyzeTree(ctx context.Context, tree core.ParseTree)
 	if err != nil {
 		return fmt.Errorf("failed to build call graph: %w", err)
 	}
+	return p.AnalyzeGraph(ctx, cg)
+}
 
+// AnalyzeGraph runs the callback on a call graph that the caller built, as
+// the indexer builds one for the index of each file. It fails on a partial
+// graph, as AnalyzeTree does.
+func (p *callgraphPlugin) AnalyzeGraph(ctx context.Context, cg *CallGraph) error {
 	if err := p.callgraphCallback(ctx, cg); err != nil {
 		return err
 	}

plugin/callgraph/processors.go

@@ -217,7 +217,6 @@ func defineClass(classDefNode *sitter.Node, treeData []byte, classNamespace stri
 
 	metadata.insideClass = true
 	processChildren(classBody, treeData, classNamespace, callGraph, metadata)
-	log.Debugf("Register class definition %s", classNamespace)
 }
 
 // functionDefinitionProcessor processes a function or a method in its own
@@ -245,8 +244,6 @@ func functionDefinitionProcessor(functionDefNode *sitter.Node, treeData []byte,
 	}
 
 	if callGraph.addDefinition(functionNamespace, functionDefNode) {
-		log.Debugf("Register function definition for %s - %s", funcName, functionNamespace)
-
 		if metadata.insideClass {
 			if keyword := profile.instanceKeyword; keyword != "" {
 				instanceNamespace := currentNamespace + namespaceSeparator + keyword + namespaceSeparator + funcName

plugin/callgraph/python.go

@@ -167,7 +167,6 @@ func functionCallProcessor(functionCallNode *sitter.Node, argumentsNode *sitter.
 		case classAssignmentNode == nil:
 		case callGraph.classConstructors[classAssignmentNode.Namespace]:
 			result.ImmediateAssignments = append(result.ImmediateAssignments, classAssignmentNode)
-			log.Debugf("Class constructed - %s in fncall for %s\n", classAssignmentNode.Namespace, functionName)
 		case callGraph.imported(classAssignmentNode.Namespace) && !callGraph.isPythonDynamicImport(classAssignmentNode.Namespace):
 			// The file cannot tell an imported class from an imported
 			// function. The value of the call is the callee, as for new X()
@@ -196,7 +195,6 @@ func functionCallProcessor(functionCallNode *sitter.Node, argumentsNode *sitter.
 	switch function.Type() {
 	case "identifier":
 		if assignment, found := searchSymbolInScopeChain(functionName, currentNamespace, callGraph); found {
-			log.Debugf("Call %s searched (direct) & resolved to %s\n", functionName, assignment.Namespace)
 			addEdge(assignment.Namespace, nil)
 			markClassAssignment(assignment)
 			return result

plugin/indexer/cache.go

@@ -6,6 +6,7 @@ import (
 
 	"github.com/safedep/code/core"
 	"github.com/safedep/code/fileindex/store"
+	"github.com/safedep/code/plugin/callgraph"
 	"github.com/safedep/dry/log"
 )
 
@@ -33,6 +34,25 @@ type CachedPlugin interface {
 	Restore(ctx context.Context, file core.File, data []byte) error
 }
 
+// GraphPlugin is a CachedPlugin that reads the call graph of a file. The
+// run builds the call graph of each file once, for the index, and gives it
+// to AnalyzeGraph, so the plugin does not build it again. A file whose call
+// graph did not build goes to Analyze.
+//
+// The index of the file is complete before AnalyzeGraph runs, so the
+// plugin cannot change the index through cg. The graph of a file that the
+// deadline cut is partial. A file that the workers finished before the
+// deadline passed gets its full graph, where Analyze would have built
+// none with a done ctx.
+type GraphPlugin interface {
+	CachedPlugin
+
+	// AnalyzeGraph runs the plugin on the tree and the call graph of a
+	// file, and returns the artifact to store. It must return the artifact
+	// that Analyze returns for the tree.
+	AnalyzeGraph(ctx context.Context, file core.File, tree core.ParseTree, cg *callgraph.CallGraph) ([]byte, error)
+}
+
 // artifactKey returns the key of the artifact of a cached plugin for a
 // file.
 func artifactKey(p pending, pl CachedPlugin) store.ArtifactKey {

plugin/indexer/cache_test.go

@@ -1,6 +1,7 @@
 package indexer
 
 import (
+	"bytes"
 	"context"
 	"errors"
 	"strconv"
@@ -10,6 +11,8 @@ import (
 	"github.com/safedep/code/core"
 	"github.com/safedep/code/fileindex"
 	"github.com/safedep/code/fileindex/store/memstore"
+	"github.com/safedep/code/parser"
+	"github.com/safedep/code/plugin/callgraph"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -34,11 +37,15 @@ func (p *countingPlugin) SupportedLanguages() []core.LanguageCode {
 }
 
 func (p *countingPlugin) Analyze(_ context.Context, file core.File, tree core.ParseTree) ([]byte, error) {
+	p.analyzed = append(p.analyzed, file.Name())
+	return lineCount(tree)
+}
+
+func lineCount(tree core.ParseTree) ([]byte, error) {
 	data, err := tree.Data()
 	if err != nil {
 		return nil, err
 	}
-	p.analyzed = append(p.analyzed, file.Name())
 	return []byte(strconv.Itoa(strings.Count(string(*data), "\n"))), nil
 }
 
@@ -131,3 +138,75 @@ func TestIndexerServesACachedPluginFromTheStore(t *testing.T) {
 		assert.Equal(t, []string{"main.js"}, broken.analyzed)
 	})
 }
+
+// graphCountingPlugin is a countingPlugin that reads the call graph of the
+// index. It records the file of each graph that it got.
+type graphCountingPlugin struct {
+	*countingPlugin
+	graphs []string
+}
+
+func (p *graphCountingPlugin) AnalyzeGraph(ctx context.Context, file core.File, tree core.ParseTree, cg *callgraph.CallGraph) ([]byte, error) {
+	built, err := callgraph.Build(ctx, tree)
+	if err != nil {
+		return nil, err
+	}
+	var got, want bytes.Buffer
+	if err := cg.Dump(&got); err != nil {
+		return nil, err
+	}
+	if err := built.Dump(&want); err != nil {
+		return nil, err
+	}
+	if cg.FileName != file.Name() || len(cg.Nodes) == 0 || got.String() != want.String() {
+		return nil, errors.New("not the call graph of the file")
+	}
+	p.graphs = append(p.graphs, file.Name())
+	return lineCount(tree)
+}
+
+func TestIndexerGivesAGraphPluginTheCallGraphOfTheIndex(t *testing.T) {
+	dir := t.TempDir()
+	writeFiles(t, dir, projectFiles)
+	fsys := appFileSystem(t, dir)
+	s := memstore.New()
+
+	pl := &graphCountingPlugin{countingPlugin: newCountingPlugin("1")}
+	result, err := runIndexer(t, context.Background(), fsys, Options{Languages: projectLanguages(t), Store: s, Plugins: []core.Plugin{pl}})
+	require.NoError(t, err)
+	assert.Empty(t, result.Report.Failed)
+	assert.Equal(t, ecmascriptNames, pl.graphs)
+	assert.Empty(t, pl.analyzed, "the run builds no second call graph through Analyze")
+
+	warm := &graphCountingPlugin{countingPlugin: newCountingPlugin("1")}
+	_, err = runIndexer(t, context.Background(), fsys, Options{Languages: projectLanguages(t), Store: s, Plugins: []core.Plugin{warm}})
+	require.NoError(t, err)
+	assert.Equal(t, ecmascriptNames, warm.restored, "the artifact of AnalyzeGraph serves the next run")
+	assert.Equal(t, map[string]string{"app/util.ts": "1", "lib/helper.js": "1", "main.js": "2"}, warm.lines)
+}
+
+func TestAnalyzeKeepsTheCallGraphOnlyForAGraphPlugin(t *testing.T) {
+	ctx := context.Background()
+	dir := t.TempDir()
+	writeFiles(t, dir, map[string]string{"main.js": projectFiles["main.js"]})
+	langs := projectLanguages(t)
+	files, _, err := enumerate(ctx, appFileSystem(t, dir), Options{Languages: langs})
+	require.NoError(t, err)
+	require.Len(t, files, 1)
+	byExtension, err := parser.LanguagesByExtension(langs)
+	require.NoError(t, err)
+	data, err := read(files[0], parser.DefaultMaxBytes)
+	require.NoError(t, err)
+	p, err := parser.NewParser(langs)
+	require.NoError(t, err)
+	defer p.Close()
+
+	file := pending{file: files[0], language: byExtension[".js"], data: data}
+	for _, keep := range []bool{false, true} {
+		o := analyze(ctx, p, file, keep)
+		require.NoError(t, o.err)
+		require.NotNil(t, o.index)
+		o.tree.Close()
+		assert.Equal(t, keep, o.graph != nil, "a run with no GraphPlugin drops the graph after the index")
+	}
+}

plugin/indexer/gounit.go

@@ -169,7 +169,7 @@ func skeletonIndex(ctx context.Context, p contentParser, file pending, tree core
 		return nil, err
 	}
 	defer skeleton.Close()
-	out, err := project(ctx, skeleton)
+	out, _, err := project(ctx, skeleton)
 	if err != nil {
 		return nil, err
 	}