weblist output disassembly now contains inlined source. (#235)

weblist output disassembly now contains inlined source.

In addition, fixed the line number assigned to instructions from inlined calls.

As an illustration, see the before and after output for a "pprof -weblist" command for a simple function:

[before](https://ghemawat.github.io/scratch/tmp/list1.html)
[after](https://ghemawat.github.io/scratch/tmp/list2.html)

Note that in the "before" page, the 7.26 second line cannot be expanded, but in the "after" page clicking on it reveals a wealth of information.

internal/driver/testdata/pprof.cpu.flat.addresses.weblist

 .legend {
   font-size: 1.25em;
 }
-.line {
-color: #aaaaaa;
+.line, .nop, .unimportant {
+  color: #aaaaaa;
 }
-.nop {
-color: #aaaaaa;
-}
-.unimportant {
-color: #cccccc;
-}
-.disasmloc {
-color: #000000;
+.inlinesrc {
+  color: #000066;
 }
 .deadsrc {
 cursor: pointer;
 Duration: 10s, Total samples = 1.12s (11.20%)<br>Total: 1.12s</div><h1>line1000</h1>testdata/file1000.src
 <pre onClick="pprof_toggle_asm(event)">
   Total:       1.10s      1.10s (flat, cum) 98.21%
-<span class=line>      1</span> <span class=deadsrc>       1.10s      1.10s line1 </span><span class=asm>               1.10s      1.10s     1000: instruction one                                  <span class=disasmloc>file1000.src:1</span>
-                   .          .     1001: instruction two                                  <span class=disasmloc>file1000.src:1</span>
-                                       ⋮
-                   .          .     1003: instruction four                                 <span class=disasmloc>file1000.src:1</span>
+<span class=line>      1</span> <span class=deadsrc>       1.10s      1.10s           line1 </span><span class=asm>               1.10s      1.10s     1000:     instruction one                                                              <span class=unimportant>file1000.src:1</span>
+                   .          .     1001:     instruction two                                                              <span class=unimportant>file1000.src:1</span>
+                                     ⋮
+                   .          .     1003:     instruction four                                                             <span class=unimportant>file1000.src:1</span>
 </span>
-<span class=line>      2</span> <span class=deadsrc>           .          . line2 </span><span class=asm>                   .          .     1002: instruction three                                <span class=disasmloc>file1000.src:2</span>
+<span class=line>      2</span> <span class=deadsrc>           .          .           line2 </span><span class=asm>                   .          .     1002:     instruction three                                                            <span class=unimportant>file1000.src:2</span>
 </span>
-<span class=line>      3</span> <span class=nop>           .          . line3 </span>
-<span class=line>      4</span> <span class=nop>           .          . line4 </span>
-<span class=line>      5</span> <span class=nop>           .          . line5 </span>
-<span class=line>      6</span> <span class=nop>           .          . line6 </span>
-<span class=line>      7</span> <span class=nop>           .          . line7 </span>
+<span class=line>      3</span> <span class=nop>           .          .           line3 </span>
+<span class=line>      4</span> <span class=nop>           .          .           line4 </span>
+<span class=line>      5</span> <span class=nop>           .          .           line5 </span>
+<span class=line>      6</span> <span class=nop>           .          .           line6 </span>
+<span class=line>      7</span> <span class=nop>           .          .           line7 </span>
 </pre>
 <h1>line3000</h1>testdata/file3000.src
 <pre onClick="pprof_toggle_asm(event)">
   Total:        10ms      1.12s (flat, cum)   100%
-<span class=line>      1</span> <span class=nop>           .          . line1 </span>
-<span class=line>      2</span> <span class=nop>           .          . line2 </span>
-<span class=line>      3</span> <span class=nop>           .          . line3 </span>
-<span class=line>      4</span> <span class=nop>           .          . line4 </span>
-<span class=line>      5</span> <span class=nop>           .          . line5 </span>
-<span class=line>      6</span> <span class=deadsrc>        10ms      1.01s line6 </span><span class=asm>                10ms      1.01s     3000: instruction one                                  <span class=disasmloc>file3000.src:6</span>
+<span class=line>      1</span> <span class=nop>           .          .           line1 </span>
+<span class=line>      2</span> <span class=nop>           .          .           line2 </span>
+<span class=line>      3</span> <span class=nop>           .          .           line3 </span>
+<span class=line>      4</span> <span class=nop>           .          .           line4 </span>
+<span class=line>      5</span> <span class=nop>           .          .           line5 </span>
+<span class=line>      6</span> <span class=deadsrc>        10ms      1.01s           line6 </span><span class=asm>                10ms      1.01s     3000:     instruction one                                                              <span class=unimportant>file3000.src:6</span>
 </span>
-<span class=line>      7</span> <span class=nop>           .          . line7 </span>
-<span class=line>      8</span> <span class=nop>           .          . line8 </span>
-<span class=line>      9</span> <span class=deadsrc>           .      110ms line9 </span><span class=asm>                   .      100ms     3001: instruction two                                  <span class=disasmloc>file3000.src:9</span>
-                   .       10ms     3002: instruction three                                <span class=disasmloc>file3000.src:9</span>
-                   .          .     3003: instruction four                                 <span class=disasmloc></span>
-                   .          .     3004: instruction five                                 <span class=disasmloc></span>
+<span class=line>      7</span> <span class=nop>           .          .           line7 </span>
+<span class=line>      8</span> <span class=nop>           .          .           line8 </span>
+<span class=line>      9</span> <span class=deadsrc>           .      110ms           line9 </span><span class=asm>                   .      100ms     3001:     instruction two                                                              <span class=unimportant>file3000.src:9</span>
+                   .       10ms     3002:     instruction three                                                            <span class=unimportant>file3000.src:9</span>
+                   .          .     3003:     instruction four                                                             <span class=unimportant></span>
+                   .          .     3004:     instruction five                                                             <span class=unimportant></span>
 </span>
-<span class=line>     10</span> <span class=nop>           .          . line0 </span>
-<span class=line>     11</span> <span class=nop>           .          . line1 </span>
-<span class=line>     12</span> <span class=nop>           .          . line2 </span>
-<span class=line>     13</span> <span class=nop>           .          . line3 </span>
-<span class=line>     14</span> <span class=nop>           .          . line4 </span>
+<span class=line>     10</span> <span class=nop>           .          .           line0 </span>
+<span class=line>     11</span> <span class=nop>           .          .           line1 </span>
+<span class=line>     12</span> <span class=nop>           .          .           line2 </span>
+<span class=line>     13</span> <span class=nop>           .          .           line3 </span>
+<span class=line>     14</span> <span class=nop>           .          .           line4 </span>
 </pre>
 
 </body>

internal/driver/webui_test.go

 		{"/", []string{"F1", "F2", "F3", "testbin", "cpu"}, true},
 		{"/top", []string{`"Name":"F2","InlineLabel":"","Flat":200,"Cum":300,"FlatFormat":"200ms","CumFormat":"300ms"}`}, false},
 		{"/source?f=" + url.QueryEscape("F[12]"),
-			[]string{"F1", "F2", "300ms line1"}, false},
+			[]string{"F1", "F2", "300ms +line1"}, false},
 		{"/peek?f=" + url.QueryEscape("F[12]"),
 			[]string{"300ms.*F1", "200ms.*300ms.*F2"}, false},
 		{"/disasm?f=" + url.QueryEscape("F[12]"),

internal/report/report.go

 				&objSymbol{
 					sym:  ms,
 					base: base,
+					file: f,
 				},
 			)
 		}
 type objSymbol struct {
 	sym  *plugin.Sym
 	base uint64
+	file plugin.ObjFile
 }
 
 // orderSyms is a wrapper type to sort []*objSymbol by a supplied comparator.
 	flat, cum       int64
 	flatDiv, cumDiv int64
 	startsBlock     bool
+	inlineCalls     []callID
+}
+
+type callID struct {
+	file string
+	line int
 }
 
 func (a *assemblyInstruction) flatValue() int64 {

internal/report/source.go

 		}
 		sourcePath = wd
 	}
+	reader := newSourceReader(sourcePath)
 
 	fmt.Fprintf(w, "Total: %s\n", rpt.formatValue(rpt.total))
 	for _, fn := range functions {
 			fns := fileNodes[filename]
 			flatSum, cumSum := fns.Sum()
 
-			fnodes, _, err := getSourceFromFile(filename, sourcePath, fns, 0, 0)
+			fnodes, _, err := getSourceFromFile(filename, reader, fns, 0, 0)
 			fmt.Fprintf(w, "ROUTINE ======================== %s in %s\n", name, filename)
 			fmt.Fprintf(w, "%10s %10s (flat, cum) %s of Total\n",
 				rpt.formatValue(flatSum), rpt.formatValue(cumSum),
 		}
 		sourcePath = wd
 	}
+	reader := newSourceReader(sourcePath)
 
 	type fileFunction struct {
 		fileName, functionName string
 		asm := assemblyPerSourceLine(symbols, fns, ff.fileName, obj)
 		start, end := sourceCoordinates(asm)
 
-		fnodes, path, err := getSourceFromFile(ff.fileName, sourcePath, fns, start, end)
+		fnodes, path, err := getSourceFromFile(ff.fileName, reader, fns, start, end)
 		if err != nil {
 			fnodes, path = getMissingFunctionSource(ff.fileName, asm, start, end)
 		}
 
 		printFunctionHeader(w, ff.functionName, path, n.Flat, n.Cum, rpt)
 		for _, fn := range fnodes {
-			printFunctionSourceLine(w, fn, asm[fn.Info.Lineno], rpt)
+			printFunctionSourceLine(w, fn, asm[fn.Info.Lineno], reader, rpt)
 		}
 		printFunctionClosing(w)
 	}
 	var lineno = 0
 	var prevline = 0
 	for _, an := range anodes {
-		if filepath.Base(an.file) == srcBase {
+		// Do not rely solely on the line number produced by Disasm
+		// since it is not what we want in the presence of inlining.
+		//
+		// E.g., suppose we are printing source code for F and this
+		// instruction is from H where F called G called H and both
+		// of those calls were inlined.  We want to use the line
+		// number from F, not from H (which is what Disasm gives us).
+		//
+		// So find the outer-most linenumber in the source file.
+		found := false
+		if frames, err := o.file.SourceLine(an.address + o.base); err == nil {
+			for i := len(frames) - 1; i >= 0; i-- {
+				if filepath.Base(frames[i].File) == srcBase {
+					for j := i - 1; j >= 0; j-- {
+						an.inlineCalls = append(an.inlineCalls, callID{frames[j].File, frames[j].Line})
+					}
+					lineno = frames[i].Line
+					found = true
+					break
+				}
+			}
+		}
+		if !found && filepath.Base(an.file) == srcBase {
 			lineno = an.line
 		}
+
 		if lineno != 0 {
 			if lineno != prevline {
 				// This instruction starts a new block
 }
 
 // printFunctionSourceLine prints a source line and the corresponding assembly.
-func printFunctionSourceLine(w io.Writer, fn *graph.Node, assembly []assemblyInstruction, rpt *Report) {
+func printFunctionSourceLine(w io.Writer, fn *graph.Node, assembly []assemblyInstruction, reader *sourceReader, rpt *Report) {
 	if len(assembly) == 0 {
 		fmt.Fprintf(w,
-			"<span class=line> %6d</span> <span class=nop>  %10s %10s %s </span>\n",
+			"<span class=line> %6d</span> <span class=nop>  %10s %10s %8s  %s </span>\n",
 			fn.Info.Lineno,
 			valueOrDot(fn.Flat, rpt), valueOrDot(fn.Cum, rpt),
-			template.HTMLEscapeString(fn.Info.Name))
+			"", template.HTMLEscapeString(fn.Info.Name))
 		return
 	}
 
 	fmt.Fprintf(w,
-		"<span class=line> %6d</span> <span class=deadsrc>  %10s %10s %s </span>",
+		"<span class=line> %6d</span> <span class=deadsrc>  %10s %10s %8s  %s </span>",
 		fn.Info.Lineno,
 		valueOrDot(fn.Flat, rpt), valueOrDot(fn.Cum, rpt),
-		template.HTMLEscapeString(fn.Info.Name))
+		"", template.HTMLEscapeString(fn.Info.Name))
+	srcIndent := indentation(fn.Info.Name)
 	fmt.Fprint(w, "<span class=asm>")
+	var curCalls []callID
 	for i, an := range assembly {
 		if an.startsBlock && i != 0 {
 			// Insert a separator between discontiguous blocks.
-			fmt.Fprintf(w, " %8s %30s\n", "", "⋮")
+			fmt.Fprintf(w, " %8s %28s\n", "", "⋮")
 		}
 
 		var fileline string
-		class := "disasmloc"
 		if an.file != "" {
 			fileline = fmt.Sprintf("%s:%d", template.HTMLEscapeString(an.file), an.line)
-			if an.line != fn.Info.Lineno {
-				class = "unimportant"
-			}
 		}
 		flat, cum := an.flat, an.cum
 		if an.flatDiv != 0 {
 		if an.cumDiv != 0 {
 			cum = cum / an.cumDiv
 		}
-		fmt.Fprintf(w, " %8s %10s %10s %8x: %s <span class=%s>%s</span>\n", "",
-			valueOrDot(flat, rpt), valueOrDot(cum, rpt),
-			an.address,
-			template.HTMLEscapeString(fmt.Sprintf("%-48s", strings.Replace(an.instruction, "\t", " ", -1))),
-			class,
+
+		// Print inlined call context.
+		for j, c := range an.inlineCalls {
+			if j < len(curCalls) && curCalls[j] == c {
+				// Skip if same as previous instruction.
+				continue
+			}
+			curCalls = nil
+			fname := trimPath(c.file)
+			fline, ok := reader.line(fname, c.line)
+			if !ok {
+				fline = ""
+			}
+			text := strings.Repeat(" ", srcIndent+4+4*j) + strings.TrimSpace(fline)
+			fmt.Fprintf(w, " %8s %10s %10s %8s  <span class=inlinesrc>%s</span> <span class=unimportant>%s:%d</span>\n",
+				"", "", "", "",
+				template.HTMLEscapeString(fmt.Sprintf("%-80s", text)),
+				template.HTMLEscapeString(filepath.Base(fname)), c.line)
+		}
+		curCalls = an.inlineCalls
+		text := strings.Repeat(" ", srcIndent+4+4*len(curCalls)) + an.instruction
+		fmt.Fprintf(w, " %8s %10s %10s %8x: %s <span class=unimportant>%s</span>\n",
+			"", valueOrDot(flat, rpt), valueOrDot(cum, rpt), an.address,
+			template.HTMLEscapeString(fmt.Sprintf("%-80s", text)),
 			template.HTMLEscapeString(fileline))
 	}
 	fmt.Fprintln(w, "</span>")
 // getSourceFromFile collects the sources of a function from a source
 // file and annotates it with the samples in fns. Returns the sources
 // as nodes, using the info.name field to hold the source code.
-func getSourceFromFile(file, sourcePath string, fns graph.Nodes, start, end int) (graph.Nodes, string, error) {
+func getSourceFromFile(file string, reader *sourceReader, fns graph.Nodes, start, end int) (graph.Nodes, string, error) {
 	file = trimPath(file)
-	f, err := openSourceFile(file, sourcePath)
-	if err != nil {
-		return nil, file, err
-	}
-
 	lineNodes := make(map[int]graph.Nodes)
+
 	// Collect source coordinates from profile.
 	const margin = 5 // Lines before first/after last sample.
 	if start == 0 {
 		}
 		lineNodes[lineno] = append(lineNodes[lineno], n)
 	}
+	if start < 1 {
+		start = 1
+	}
 
 	var src graph.Nodes
-	buf := bufio.NewReader(f)
-	lineno := 1
-	for {
-		line, err := buf.ReadString('\n')
-		if err != nil {
-			if err != io.EOF {
-				return nil, file, err
-			}
-			if line == "" {
-				break
-			}
-		}
-		if lineno >= start {
-			flat, cum := lineNodes[lineno].Sum()
-
-			src = append(src, &graph.Node{
-				Info: graph.NodeInfo{
-					Name:   strings.TrimRight(line, "\n"),
-					Lineno: lineno,
-				},
-				Flat: flat,
-				Cum:  cum,
-			})
-		}
-		lineno++
-		if lineno > end {
+	for lineno := start; lineno <= end; lineno++ {
+		line, ok := reader.line(file, lineno)
+		if !ok {
 			break
 		}
+		flat, cum := lineNodes[lineno].Sum()
+		src = append(src, &graph.Node{
+			Info: graph.NodeInfo{
+				Name:   strings.TrimRight(line, "\n"),
+				Lineno: lineno,
+			},
+			Flat: flat,
+			Cum:  cum,
+		})
+	}
+	if err := reader.fileError(file); err != nil {
+		return nil, file, err
 	}
 	return src, file, nil
 }
 	return fnodes, filename
 }
 
+// sourceReader provides access to source code with caching of file contents.
+type sourceReader struct {
+	searchPath string
+
+	// files maps from path name to a list of lines.
+	// files[*][0] is unused since line numbering starts at 1.
+	files map[string][]string
+
+	// errors collects errors encountered per file.  These errors are
+	// consulted before returning out of these module.
+	errors map[string]error
+}
+
+func newSourceReader(searchPath string) *sourceReader {
+	return &sourceReader{
+		searchPath,
+		make(map[string][]string),
+		make(map[string]error),
+	}
+}
+
+func (reader *sourceReader) fileError(path string) error {
+	return reader.errors[path]
+}
+
+func (reader *sourceReader) line(path string, lineno int) (string, bool) {
+	lines, ok := reader.files[path]
+	if !ok {
+		// Read and cache file contents.
+		lines = []string{""} // Skip 0th line
+		f, err := openSourceFile(path, reader.searchPath)
+		if err != nil {
+			reader.errors[path] = err
+		} else {
+			s := bufio.NewScanner(f)
+			for s.Scan() {
+				lines = append(lines, s.Text())
+			}
+			f.Close()
+			if s.Err() != nil {
+				reader.errors[path] = err
+			}
+		}
+		reader.files[path] = lines
+	}
+	if lineno <= 0 || lineno >= len(lines) {
+		return "", false
+	}
+	return lines[lineno], true
+}
+
 // openSourceFile opens a source file from a name encoded in a
 // profile. File names in a profile after often relative paths, so
 // search them in each of the paths in searchPath (or CWD by default),
 	}
 	return path
 }
+
+func indentation(line string) int {
+	column := 0
+	for _, c := range line {
+		if c == ' ' {
+			column++
+		} else if c == '\t' {
+			column++
+			for column%8 != 0 {
+				column++
+			}
+		} else {
+			break
+		}
+	}
+	return column
+}

internal/report/source_html.go

 .legend {
   font-size: 1.25em;
 }
-.line {
-color: #aaaaaa;
+.line, .nop, .unimportant {
+  color: #aaaaaa;
 }
-.nop {
-color: #aaaaaa;
-}
-.unimportant {
-color: #cccccc;
-}
-.disasmloc {
-color: #000000;
+.inlinesrc {
+  color: #000066;
 }
 .deadsrc {
 cursor: pointer;

internal/report/source_test.go

+package report
+
+import (
+	"bytes"
+	"os"
+	"path/filepath"
+	"regexp"
+	"runtime"
+	"strings"
+	"testing"
+
+	"github.com/google/pprof/internal/binutils"
+	"github.com/google/pprof/profile"
+)
+
+func TestWebList(t *testing.T) {
+	if runtime.GOOS != "linux" {
+		t.Skip("weblist only tested on linux")
+	}
+
+	cpu := readProfile(filepath.Join("testdata", "sample.cpu"), t)
+	rpt := New(cpu, &Options{
+		OutputFormat: WebList,
+		Symbol:       regexp.MustCompile("busyLoop"),
+		SampleValue:  func(v []int64) int64 { return v[1] },
+		SampleUnit:   cpu.SampleType[1].Unit,
+	})
+	buf := bytes.NewBuffer(nil)
+	if err := Generate(buf, rpt, &binutils.Binutils{}); err != nil {
+		t.Fatalf("could not generate weblist: %v", err)
+	}
+	output := buf.String()
+
+	for _, expect := range []string{"func busyLoop", "callq", "math.Abs"} {
+		if !strings.Contains(output, expect) {
+			t.Errorf("weblist output does not contain '%s':\n%s", expect, output)
+		}
+	}
+}
+
+func TestIndentation(t *testing.T) {
+	for _, c := range []struct {
+		str    string
+		indent int
+	}{
+		{"", 0},
+		{"foobar", 0},
+		{"  foo", 2},
+		{"\tfoo", 8},
+		{"\t foo", 9},
+		{"  \tfoo", 8},
+		{"       \tfoo", 8},
+		{"        \tfoo", 16},
+	} {
+		if n := indentation(c.str); n != c.indent {
+			t.Errorf("indentation for %v: expect %d, got %d\n", c.str, c.indent, n)
+		}
+	}
+}
+
+func readProfile(fname string, t *testing.T) *profile.Profile {
+	file, err := os.Open(fname)
+	if err != nil {
+		t.Fatalf("%s: could not open profile: %v", fname, err)
+	}
+	defer file.Close()
+	p, err := profile.Parse(file)
+	if err != nil {
+		t.Fatalf("%s: could not parse profile: %v", fname, err)
+	}
+
+	// Fix file names so they do not include absolute path names.
+	fix := func(s string) string {
+		const testdir = "/internal/report/"
+		pos := strings.Index(s, testdir)
+		if pos == -1 {
+			return s
+		}
+		return s[pos+len(testdir):]
+	}
+	for _, m := range p.Mapping {
+		m.File = fix(m.File)
+	}
+	for _, f := range p.Function {
+		f.Filename = fix(f.Filename)
+	}
+
+	return p
+}

internal/report/testdata/README.md

+sample/ contains a sample program that can be profiled.
+sample.bin is its x86-64 binary.
+sample.cpu is a profile generated by sample.bin.
+
+To update the binary and profile:
+
+```shell
+go build -o sample.bin ./sample
+./sample.bin -cpuprofile sample.cpu
+```

internal/report/testdata/sample/sample.go

+// sample program that is used to produce some of the files in
+// pprof/internal/report/testdata.
+package main
+
+import (
+	"flag"
+	"fmt"
+	"log"
+	"math"
+	"os"
+	"runtime/pprof"
+)
+
+var cpuProfile = flag.String("cpuprofile", "", "where to write cpu profile")
+
+func main() {
+	flag.Parse()
+	f, err := os.Create(*cpuProfile)
+	if err != nil {
+		log.Fatal("could not create CPU profile: ", err)
+	}
+	if err := pprof.StartCPUProfile(f); err != nil {
+		log.Fatal("could not start CPU profile: ", err)
+	}
+	defer pprof.StopCPUProfile()
+	busyLoop()
+}
+
+func busyLoop() {
+	m := make(map[int]int)
+	for i := 0; i < 1000000; i++ {
+		m[i] = i + 10
+	}
+	var sum float64
+	for i := 0; i < 100; i++ {
+		for _, v := range m {
+			sum += math.Abs(float64(v))
+		}
+	}
+	fmt.Println("Sum", sum)
+}