Skip to content

Commit

Permalink
add VALAST_PROFILE to emit performance profiling information
Browse files Browse the repository at this point in the history 
This can be useful for debugging why some complex/nested data structures, such
as those reported in https://github.com/sourcegraph/sourcegraph/pull/18189
are not being handled quickly by Valast:

```
$ VALAST_PROFILE=t go test -v -run='TestUnionMerge/#2' ./cmd/frontend/graphqlbackend/
=== RUN   TestUnionMerge
=== RUN   TestUnionMerge/#2
valast: profile
1242026902ns: *graphqlbackend.SearchResultsResolver
  1242001613ns: graphqlbackend.SearchResultsResolver
    1241965682ns: []graphqlbackend.SearchResultResolver
      631554070ns: *graphqlbackend.RepositoryResolver
        631552406ns: *graphqlbackend.RepositoryResolver
          631549333ns: graphqlbackend.RepositoryResolver
            631541623ns: *types.Repo
              409622256ns: types.Repo
                194531303ns: api.RepoName
      610281838ns: *graphqlbackend.RepositoryResolver
        610280747ns: *graphqlbackend.RepositoryResolver
          610277705ns: graphqlbackend.RepositoryResolver
            610242182ns: *types.Repo
              408077957ns: types.Repo
                185258694ns: api.RepoName
      7893ns: *graphqlbackend.FileMatchResolver
        7140ns: *graphqlbackend.FileMatchResolver
          5401ns: graphqlbackend.FileMatchResolver
            3438ns: graphqlbackend.FileMatch
              536ns: string
      33541ns: *graphqlbackend.FileMatchResolver
        31856ns: *graphqlbackend.FileMatchResolver
          29326ns: graphqlbackend.FileMatchResolver
            15457ns: graphqlbackend.FileMatch
              581ns: string
      7347ns: *graphqlbackend.CommitSearchResultResolver
        6671ns: *graphqlbackend.CommitSearchResultResolver
          5591ns: graphqlbackend.CommitSearchResultResolver
            509ns: string
            1856ns: *graphqlbackend.highlightedString
              702ns: graphqlbackend.highlightedString
      14634ns: *graphqlbackend.CommitSearchResultResolver
        13880ns: *graphqlbackend.CommitSearchResultResolver
          12711ns: graphqlbackend.CommitSearchResultResolver
            623ns: string
            8674ns: *graphqlbackend.highlightedString
              7160ns: graphqlbackend.highlightedString
      7210ns: *graphqlbackend.CommitSearchResultResolver
        6198ns: *graphqlbackend.CommitSearchResultResolver
          4549ns: graphqlbackend.CommitSearchResultResolver
            591ns: string
      49168ns: *graphqlbackend.CommitSearchResultResolver
        34915ns: *graphqlbackend.CommitSearchResultResolver
          27193ns: graphqlbackend.CommitSearchResultResolver
valast: profile
1246689469ns: *graphqlbackend.SearchResultsResolver
  1246683327ns: graphqlbackend.SearchResultsResolver
    1246675918ns: []graphqlbackend.SearchResultResolver
      605954511ns: *graphqlbackend.RepositoryResolver
        605951599ns: *graphqlbackend.RepositoryResolver
          605948656ns: graphqlbackend.RepositoryResolver
            605939227ns: *types.Repo
              398690970ns: types.Repo
                196774754ns: api.RepoName
      640656293ns: *graphqlbackend.RepositoryResolver
        640655289ns: *graphqlbackend.RepositoryResolver
          640647478ns: graphqlbackend.RepositoryResolver
            640634530ns: *types.Repo
              415481187ns: types.Repo
                191840428ns: api.RepoName
      11750ns: *graphqlbackend.FileMatchResolver
        11086ns: *graphqlbackend.FileMatchResolver
          9437ns: graphqlbackend.FileMatchResolver
            7961ns: graphqlbackend.FileMatch
              657ns: string
      7593ns: *graphqlbackend.FileMatchResolver
        6844ns: *graphqlbackend.FileMatchResolver
          5599ns: graphqlbackend.FileMatchResolver
            3269ns: graphqlbackend.FileMatch
              497ns: string
      10136ns: *graphqlbackend.CommitSearchResultResolver
        9470ns: *graphqlbackend.CommitSearchResultResolver
          8263ns: graphqlbackend.CommitSearchResultResolver
            484ns: string
            1711ns: *graphqlbackend.highlightedString
              530ns: graphqlbackend.highlightedString
      7516ns: *graphqlbackend.CommitSearchResultResolver
        6869ns: *graphqlbackend.CommitSearchResultResolver
          5810ns: graphqlbackend.CommitSearchResultResolver
            585ns: string
            2194ns: *graphqlbackend.highlightedString
              706ns: graphqlbackend.highlightedString
      5283ns: *graphqlbackend.CommitSearchResultResolver
        4576ns: *graphqlbackend.CommitSearchResultResolver
          3292ns: graphqlbackend.CommitSearchResultResolver
            544ns: string
      9954ns: *graphqlbackend.CommitSearchResultResolver
        8253ns: *graphqlbackend.CommitSearchResultResolver
          6366ns: graphqlbackend.CommitSearchResultResolver
--- PASS: TestUnionMerge (2.78s)
    --- PASS: TestUnionMerge/#2 (2.78s)
PASS
ok  	github.com/sourcegraph/sourcegraph/cmd/frontend/graphqlbackend	3.230s
```

Signed-off-by: Stephen Gutekanst <[email protected]>
  • Loading branch information
@slimsag
slimsag committed Feb 12, 2021
1 parent 4d8fa92 commit ac3cf79
Showing 1 changed file with 61 additions and 10 deletions.
71 changes: 61 additions & 10 deletions valast.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,10 +7,12 @@ import (
"go/format"
"go/token"
"io"
"os"
"reflect"
"sort"
"strconv"
"strings"
"time"

"github.com/shurcooL/go-goon/bypass"
"golang.org/x/tools/go/packages"
Expand Down Expand Up @@ -284,10 +286,25 @@ func (c *cycleDetector) pop(ptr interface{}) {
// &foo{id: 123, bar: &foo{id: 123, bar: nil}}
//
func AST(v reflect.Value, opt *Options) (Result, error) {
return computeAST(v, opt, &cycleDetector{})
var prof *profiler
wantProfile, _ := strconv.ParseBool(os.Getenv("VALAST_PROFILE"))
if wantProfile {
prof = &profiler{}
}
r, err := computeASTProfiled(v, opt, &cycleDetector{}, prof)
prof.dump()
return r, err
}

func computeASTProfiled(v reflect.Value, opt *Options, cycleDetector *cycleDetector, profiler *profiler) (Result, error) {
profiler.push(v)
start := time.Now()
r, err := computeAST(v, opt, cycleDetector, profiler)
profiler.pop(start)
return r, err
}

func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Result, error) {
func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector, profiler *profiler) (Result, error) {
if opt == nil {
opt = &Options{}
}
Expand Down Expand Up @@ -359,7 +376,7 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
requiresUnexported bool
)
for i := 0; i < vv.Len(); i++ {
elem, err := computeAST(vv.Index(i), opt.withUnqualify(), cycleDetector)
elem, err := computeASTProfiled(vv.Index(i), opt.withUnqualify(), cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand Down Expand Up @@ -387,9 +404,9 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
}, nil
}
if opt.Unqualify {
return computeAST(unexported(vv.Elem()), opt.withUnqualify(), cycleDetector)
return computeASTProfiled(unexported(vv.Elem()), opt.withUnqualify(), cycleDetector, profiler)
}
v, err := computeAST(unexported(vv.Elem()), opt, cycleDetector)
v, err := computeASTProfiled(unexported(vv.Elem()), opt, cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand All @@ -415,7 +432,7 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
})
for _, key := range keys {
value := vv.MapIndex(key)
k, err := computeAST(key, opt.withUnqualify(), cycleDetector)
k, err := computeASTProfiled(key, opt.withUnqualify(), cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand All @@ -429,7 +446,7 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
if k.OmittedUnexported {
omittedUnexported = true
}
v, err := computeAST(value, opt.withUnqualify(), cycleDetector)
v, err := computeASTProfiled(value, opt.withUnqualify(), cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand Down Expand Up @@ -485,7 +502,7 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
// cyclic data structure detected
return Result{AST: ast.NewIdent("nil")}, nil
}
elem, err := computeAST(vv.Elem(), opt, cycleDetector)
elem, err := computeASTProfiled(vv.Elem(), opt, cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand Down Expand Up @@ -562,7 +579,7 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
requiresUnexported bool
)
for i := 0; i < vv.Len(); i++ {
elem, err := computeAST(vv.Index(i), opt.withUnqualify(), cycleDetector)
elem, err := computeASTProfiled(vv.Index(i), opt.withUnqualify(), cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand Down Expand Up @@ -599,7 +616,7 @@ func computeAST(v reflect.Value, opt *Options, cycleDetector *cycleDetector) (Re
if unexported(v.Field(i)).IsZero() {
continue
}
value, err := computeAST(unexported(v.Field(i)), opt.withUnqualify(), cycleDetector)
value, err := computeASTProfiled(unexported(v.Field(i)), opt.withUnqualify(), cycleDetector, profiler)
if err != nil {
return Result{}, err
}
Expand Down Expand Up @@ -946,3 +963,37 @@ func valueLess(i, j reflect.Value) bool {
return true
}
}

type profiler struct {
stack []reflect.Value
invertedStackMessages []string
}

func (p *profiler) push(v reflect.Value) {
if p == nil {
return
}
p.stack = append(p.stack, v)
}

func (p *profiler) pop(startTime time.Time) {
if p == nil {
return
}
d := time.Since(startTime)
v := p.stack[len(p.stack)-1].Interface()
p.stack = p.stack[:len(p.stack)-1]
stackSize := len(p.stack)
msg := fmt.Sprintf("%s%vns: %T\n", strings.Repeat(" ", stackSize), d.Nanoseconds(), v)
p.invertedStackMessages = append(p.invertedStackMessages, msg)
}

func (p *profiler) dump() {
if p == nil {
return
}
fmt.Println("valast: profile")
for i := len(p.invertedStackMessages) - 1; i > 0; i-- {
fmt.Print(p.invertedStackMessages[i])
}
}

0 comments on commit ac3cf79

Please sign in to comment.