From 45f589b2a755c6c55dfdbf1c634caaa028956edf Mon Sep 17 00:00:00 2001 From: Ashutosh Narkar Date: Mon, 2 Jul 2018 09:52:29 -0700 Subject: [PATCH] Sort profiler result based on criteria to return top N results Signed-off-by: Ashutosh Narkar --- cmd/eval.go | 2 +- profiler/profiler.go | 226 ++++++++++++++++++--------- profiler/profiler_test.go | 313 ++++++++++++++++++++++++++++++++++---- 3 files changed, 439 insertions(+), 102 deletions(-) diff --git a/cmd/eval.go b/cmd/eval.go index f457611f60..bb6beeefd2 100644 --- a/cmd/eval.go +++ b/cmd/eval.go @@ -248,7 +248,7 @@ func eval(args []string, params evalCommandParams) (err error) { } if params.profile { - result.Profile = p.Report() + result.Profile = p.ReportByFile() } switch params.outputFormat.String() { diff --git a/profiler/profiler.go b/profiler/profiler.go index 6bd71e7272..48354757e7 100644 --- a/profiler/profiler.go +++ b/profiler/profiler.go @@ -2,7 +2,7 @@ // Use of this source code is governed by an Apache2 // license that can be found in the LICENSE file. -// Package profiler computes and reports on the time spent on expressions +// Package profiler computes and reports on the time spent on expressions. package profiler import ( @@ -13,27 +13,23 @@ import ( "github.com/open-policy-agent/opa/topdown" ) -// Profiler computes and reports on the time spent on expressions +// Profiler computes and reports on the time spent on expressions. type Profiler struct { - hits map[string]map[Position]ExprStats + hits map[string]map[int]ExprStats activeTimer time.Time - prevExpr ExprInfo + prevExpr exprInfo } -// ExprInfo stores information about an expression -type ExprInfo struct { - index int - file string - row int - col int - text []byte - op string +// exprInfo stores information about an expression. +type exprInfo struct { + location *ast.Location + op topdown.Op } -// New returns a new Profiler object +// New returns a new Profiler object. func New() *Profiler { return &Profiler{ - hits: map[string]map[Position]ExprStats{}, + hits: map[string]map[int]ExprStats{}, } } @@ -42,8 +38,9 @@ func (p *Profiler) Enabled() bool { return true } -// Report returns a profiler report -func (p *Profiler) Report() (report Report) { +// ReportByFile returns a profiler report for expressions grouped by the +// file name. For each file the results are sorted by increasing row number. +func (p *Profiler) ReportByFile() (report Report) { p.processLastExpr() report.Files = map[string]*FileReport{} for file, hits := range p.hits { @@ -63,115 +60,146 @@ func (p *Profiler) Report() (report Report) { return report } -// Trace updates the profiler state +// ReportTopNResults returns the top N results based on the given +// criteria. If N <= 0, all the results based on the criteria are returned. +func (p *Profiler) ReportTopNResults(numResults int, criteria []string) []ExprStats { + p.processLastExpr() + stats := []ExprStats{} + + for _, hits := range p.hits { + for _, stat := range hits { + stats = append(stats, stat) + } + } + + // allowed criteria for sorting results + allowedCriteria := map[string]lessFunc{} + allowedCriteria["EvalTime"] = func(stat1, stat2 *ExprStats) bool { + return stat1.ExprTimeNs > stat2.ExprTimeNs + } + allowedCriteria["NumEval"] = func(stat1, stat2 *ExprStats) bool { + return stat1.NumEval > stat2.NumEval + } + allowedCriteria["NumRedo"] = func(stat1, stat2 *ExprStats) bool { + return stat1.NumRedo > stat2.NumRedo + } + + sortFuncs := []lessFunc{} + + for _, cr := range criteria { + if fn, ok := allowedCriteria[cr]; ok { + sortFuncs = append(sortFuncs, fn) + } + } + + // if no criteria return all the stats + if len(sortFuncs) == 0 { + return stats + } + + orderedBy(sortFuncs).Sort(stats) + + // if desired number of results to be returned is less than or + // equal to 0 or exceed total available results, + // return all the stats + if numResults <= 0 || numResults > len(stats) { + return stats + } + return stats[:numResults] + +} + +// Trace updates the profiler state. func (p *Profiler) Trace(event *topdown.Event) { switch event.Op { case topdown.EvalOp: if expr, ok := event.Node.(*ast.Expr); ok && expr != nil { - p.processExpr(expr, "Eval") + p.processExpr(expr, event.Op) } case topdown.RedoOp: if expr, ok := event.Node.(*ast.Expr); ok && expr != nil { - p.processExpr(expr, "Redo") + p.processExpr(expr, event.Op) } } } -func (p *Profiler) processExpr(expr *ast.Expr, op string) { +func (p *Profiler) processExpr(expr *ast.Expr, eventType topdown.Op) { // set the active timer on the first expression if p.activeTimer.IsZero() { p.activeTimer = time.Now() - p.prevExpr = ExprInfo{ - index: expr.Index, - file: expr.Location.File, - row: expr.Location.Row, - col: expr.Location.Col, - op: op, - text: expr.Location.Text, + p.prevExpr = exprInfo{ + op: eventType, + location: expr.Location, } return } // record the profiler results for the previous expression - hits, ok := p.hits[p.prevExpr.file] + file := p.prevExpr.location.File + hits, ok := p.hits[file] if !ok { - hits = map[Position]ExprStats{} - hits[Position{p.prevExpr.row}] = getProfilerStats(p.prevExpr, p.activeTimer) - p.hits[p.prevExpr.file] = hits + hits = map[int]ExprStats{} + hits[p.prevExpr.location.Row] = getProfilerStats(p.prevExpr, p.activeTimer) + p.hits[file] = hits } else { - pStats, ok := hits[Position{p.prevExpr.row}] + pos := p.prevExpr.location.Row + pStats, ok := hits[pos] if !ok { - hits[Position{p.prevExpr.row}] = getProfilerStats(p.prevExpr, p.activeTimer) + hits[pos] = getProfilerStats(p.prevExpr, p.activeTimer) } else { - pStats.TotalTimeNs += time.Since(p.activeTimer).Nanoseconds() - if p.prevExpr.op == "Eval" { + pStats.ExprTimeNs += time.Since(p.activeTimer).Nanoseconds() + + switch p.prevExpr.op { + case topdown.EvalOp: pStats.NumEval++ - } else { + case topdown.RedoOp: pStats.NumRedo++ } - hits[Position{p.prevExpr.row}] = pStats + hits[pos] = pStats } } // reset active timer and expression p.activeTimer = time.Now() - p.prevExpr = ExprInfo{ - index: expr.Index, - file: expr.Location.File, - row: expr.Location.Row, - col: expr.Location.Col, - op: op, - text: expr.Location.Text, + p.prevExpr = exprInfo{ + op: eventType, + location: expr.Location, } } func (p *Profiler) processLastExpr() { - loc := ast.NewLocation(p.prevExpr.text, p.prevExpr.file, p.prevExpr.row, p.prevExpr.col) expr := ast.Expr{ - Location: loc, - Index: p.prevExpr.index, + Location: p.prevExpr.location, } p.processExpr(&expr, p.prevExpr.op) } -// Position represents a file location. -type Position struct { - Row int `json:"row"` -} - -func getProfilerStats(expr ExprInfo, timer time.Time) ExprStats { +func getProfilerStats(expr exprInfo, timer time.Time) ExprStats { profilerStats := ExprStats{} - profilerStats.TotalTimeNs = time.Since(timer).Nanoseconds() - profilerStats.Index = expr.index + profilerStats.ExprTimeNs = time.Since(timer).Nanoseconds() + profilerStats.Location = expr.location - profilerStats.Row = expr.row - profilerStats.Col = expr.col - profilerStats.Text = string(expr.text) - - if expr.op == "Eval" { + switch expr.op { + case topdown.EvalOp: profilerStats.NumEval = 1 - } else { + case topdown.RedoOp: profilerStats.NumRedo = 1 } - return profilerStats } -// ExprStats represents the result of profiling an expression +// ExprStats represents the result of profiling an expression. type ExprStats struct { - Index int `json:"index"` - TotalTimeNs int64 `json:"totalTimeNs"` - NumEval int `json:"numEval"` - NumRedo int `json:"numRedo"` - Row int `json:"row"` - Col int `json:"col"` - Text string `json:"text"` + ExprTimeNs int64 `json:"total_time_ns"` + NumEval int `json:"num_eval"` + NumRedo int `json:"num_redo"` + Location *ast.Location `json:"location"` } func sortStatsByRow(ps []ExprStats) { sort.Slice(ps, func(i, j int) bool { - return ps[i].Row < ps[j].Row + return ps[i].Location.Row < ps[j].Location.Row }) } @@ -180,7 +208,61 @@ type Report struct { Files map[string]*FileReport `json:"files"` } -// FileReport represents a profiler report for a single file +// FileReport represents a profiler report for a single file. type FileReport struct { Result []ExprStats `json:"result"` } + +// Helper interfaces and methods for sorting a slice of ExprStats structs +// based on multiple fields. + +type lessFunc func(p1, p2 *ExprStats) bool + +// multiSorter implements the Sort interface, sorting the changes within. +type multiSorter struct { + stats []ExprStats + less []lessFunc +} + +// Sort sorts the argument slice according to the less functions passed to OrderedBy. +func (ms *multiSorter) Sort(stats []ExprStats) { + ms.stats = stats + sort.Sort(ms) +} + +// orderedBy returns a Sorter that sorts using the less functions, in order. +func orderedBy(less []lessFunc) *multiSorter { + return &multiSorter{ + less: less, + } +} + +// Len is part of sort.Interface. +func (ms *multiSorter) Len() int { + return len(ms.stats) +} + +// Swap is part of sort.Interface. +func (ms *multiSorter) Swap(i, j int) { + ms.stats[i], ms.stats[j] = ms.stats[j], ms.stats[i] +} + +// Less is part of sort.Interface. It is implemented by looping along the +// less functions until it finds a comparison that discriminates between +// the two items. +func (ms *multiSorter) Less(i, j int) bool { + p, q := &ms.stats[i], &ms.stats[j] + // Try all but the last comparison. + var k int + for k = 0; k < len(ms.less)-1; k++ { + less := ms.less[k] + switch { + case less(p, q): + return true + case less(q, p): + return false + } + // p == q; try the next comparison. + } + return ms.less[k](p, q) +} diff --git a/profiler/profiler_test.go b/profiler/profiler_test.go index e3ebc23175..27bf98562c 100644 --- a/profiler/profiler_test.go +++ b/profiler/profiler_test.go @@ -62,7 +62,7 @@ baz { t.Fatal(err) } - report := profiler.Report() + report := profiler.ReportByFile() fr, ok := report.Files["test.rego"] if !ok { @@ -72,9 +72,28 @@ baz { if len(fr.Result) != 11 { t.Fatalf("Expected file report length to be 11 instead got %v", len(fr.Result)) } + + expectedNumEval := []int{1, 2, 1, 1, 1, 1633, 1, 1, 1, 1, 1} + expectedNumRedo := []int{1, 0, 0, 1, 1633, 0, 1, 1, 1, 1, 0} + expectedRow := []int{4, 5, 6, 10, 11, 12, 16, 17, 18, 22, 23} + + for idx, actualExprStat := range fr.Result { + if actualExprStat.NumEval != expectedNumEval[idx] { + t.Fatalf("Index %v: Expected number of evals %v but got %v", idx, expectedNumEval[idx], actualExprStat.NumEval) + } + + if actualExprStat.NumRedo != expectedNumRedo[idx] { + t.Fatalf("Index %v: Expected number of redos %v but got %v", idx, expectedNumRedo[idx], actualExprStat.NumRedo) + } + + if actualExprStat.Location.Row != expectedRow[idx] { + t.Fatalf("Index %v: Expected row %v but got %v", idx, expectedRow[idx], actualExprStat.Location.Row) + } + + } } -func TestProfileSleepCmd(t *testing.T) { +func TestProfileCheckExprDuration(t *testing.T) { profiler := New() ast.RegisterBuiltin(&ast.Builtin{ @@ -93,8 +112,8 @@ func TestProfileSleepCmd(t *testing.T) { module := `package test - foo { - test.sleep("1s") + foo { + test.sleep("100ms") }` _, err := ast.ParseModule("test.rego", module) @@ -115,7 +134,7 @@ func TestProfileSleepCmd(t *testing.T) { t.Fatal(err) } - report := profiler.Report() + report := profiler.ReportByFile() fr, ok := report.Files["test.rego"] if !ok { @@ -126,32 +145,268 @@ func TestProfileSleepCmd(t *testing.T) { t.Fatalf("Expected file report length to be 1 instead got %v", len(fr.Result)) } - if fr.Result[0].Index != 0 { - t.Fatalf("Expected Index is 0 but got %v", fr.Result[0].Index) + if string(fr.Result[0].Location.Text) != "test.sleep(\"100ms\")" { + t.Fatalf("Expected text is test.sleep(\"100ms\") but got %v", string(fr.Result[0].Location.Text)) } - if fr.Result[0].NumEval != 1 { - t.Fatalf("Expected number of evals is 1 but got %v", fr.Result[0].NumEval) - } - - if fr.Result[0].NumRedo != 1 { - t.Fatalf("Expected number of redo is 1 but got %v", fr.Result[0].NumRedo) - } - - if fr.Result[0].Row != 4 { - t.Fatalf("Expected row is 4 but got %v", fr.Result[0].Row) - } - - if fr.Result[0].Col != 4 { - t.Fatalf("Expected col is 4 but got %v", fr.Result[0].Col) - } - - if fr.Result[0].Text != "test.sleep(\"1s\")" { - t.Fatalf("Expected text is test.sleep(\"1s\") but got %v", fr.Result[0].Text) - } - - if fr.Result[0].TotalTimeNs <= time.Duration(1*time.Second).Nanoseconds() { - t.Fatalf("Expected eval time is atleast 1 sec but got %v", fr.Result[0].TotalTimeNs) + if fr.Result[0].ExprTimeNs <= time.Duration(50*time.Millisecond).Nanoseconds() { + t.Fatalf("Expected eval time is atleast 100 msec but got %v", fr.Result[0].ExprTimeNs) } } + +func TestProfilerReportTopNResultsNoCriteria(t *testing.T) { + profiler := New() + module := `package test + +foo { + bar + not baz + bee +} + +bee { + nums = ["a", "b", "c", "d"] + num = nums[_] + contains(num, "test") +} + +bar { + a := 1 + b := 2 + a != b +} + +baz { + true + false + true +}` + + _, err := ast.ParseModule("test.rego", module) + if err != nil { + t.Fatal(err) + } + + eval := rego.New( + rego.Module("test.rego", module), + rego.Query("data.test.foo"), + rego.Tracer(profiler), + ) + + ctx := context.Background() + _, err = eval.Eval(ctx) + + if err != nil { + t.Fatal(err) + } + + stats := profiler.ReportTopNResults(0, []string{}) + + expectedResLen := 12 + if len(stats) != expectedResLen { + t.Fatalf("Expected %v stats instead got %v", expectedResLen, len(stats)) + } +} + +func TestProfilerReportTopNResultsOneCriteria(t *testing.T) { + profiler := New() + module := `package test + +foo { + bar + not baz + bee +} + +bee { + nums = ["a", "b", "c", "d"] + num = nums[_] + contains(num, "test") +} + +bar { + a := 1 + b := 2 + a != b +} + +baz { + true + false + true +}` + + _, err := ast.ParseModule("test.rego", module) + if err != nil { + t.Fatal(err) + } + + eval := rego.New( + rego.Module("test.rego", module), + rego.Query("data.test.foo"), + rego.Tracer(profiler), + ) + + ctx := context.Background() + _, err = eval.Eval(ctx) + + if err != nil { + t.Fatal(err) + } + + stats := profiler.ReportTopNResults(5, []string{"EvalTime"}) + + expectedResLen := 5 + if len(stats) != expectedResLen { + t.Fatalf("Expected %v stats instead got %v", expectedResLen, len(stats)) + } + + var i int + for i = 0; i < len(stats)-1; i++ { + if stats[i].ExprTimeNs < stats[i+1].ExprTimeNs { + t.Fatalf("Results not sorted in decreasing order of evaluation times") + } + } +} + +func TestProfilerReportTopNResultsTwoCriteria(t *testing.T) { + profiler := New() + module := `package test + +foo { + bar + not baz + bee +} + +bee { + nums = ["a", "b", "c", "d"] + num = nums[_] + contains(num, "test") +} + +bar { + a := 1 + b := 2 + a != b +} + +baz { + true + false + true +}` + + _, err := ast.ParseModule("test.rego", module) + if err != nil { + t.Fatal(err) + } + + eval := rego.New( + rego.Module("test.rego", module), + rego.Query("data.test.foo"), + rego.Tracer(profiler), + ) + + ctx := context.Background() + _, err = eval.Eval(ctx) + + if err != nil { + t.Fatal(err) + } + + stats := profiler.ReportTopNResults(5, []string{"NumEval", "EvalTime"}) + + expectedResLen := 5 + if len(stats) != expectedResLen { + t.Fatalf("Expected %v stats instead got %v", expectedResLen, len(stats)) + } + + var i int + for i = 0; i < len(stats)-1; i++ { + if stats[i].NumEval < stats[i+1].NumEval { + t.Fatalf("Results not sorted in decreasing order of number of evaluations") + } + + if stats[i].NumEval == stats[i+1].NumEval { + if stats[i].ExprTimeNs < stats[i+1].ExprTimeNs { + t.Fatalf("Results not sorted in decreasing order of evaluation times") + } + } + } +} + +func TestProfilerReportTopNResultsThreeCriteria(t *testing.T) { + profiler := New() + module := `package test + +foo { + bar + not baz + bee +} + +bee { + nums = ["a", "b", "c", "d"] + num = nums[_] + contains(num, "test") +} + +bar { + a := 1 + b := 2 + a != b +} + +baz { + true + false + true +}` + + _, err := ast.ParseModule("test.rego", module) + if err != nil { + t.Fatal(err) + } + + eval := rego.New( + rego.Module("test.rego", module), + rego.Query("data.test.foo"), + rego.Tracer(profiler), + ) + + ctx := context.Background() + _, err = eval.Eval(ctx) + + if err != nil { + t.Fatal(err) + } + + stats := profiler.ReportTopNResults(10, []string{"NumEval", "NumRedo", "EvalTime"}) + + expectedResLen := 10 + if len(stats) != expectedResLen { + t.Fatalf("Expected %v stats instead got %v", expectedResLen, len(stats)) + } + + var i int + for i = 0; i < len(stats)-1; i++ { + if stats[i].NumEval < stats[i+1].NumEval { + t.Fatalf("Results not sorted in decreasing order of number of evaluations") + } + + if stats[i].NumEval == stats[i+1].NumEval { + + if stats[i].NumRedo < stats[i+1].NumRedo { + t.Fatalf("Results not sorted in decreasing order of number of redos") + } + + if stats[i].NumRedo == stats[i+1].NumRedo { + if stats[i].ExprTimeNs < stats[i+1].ExprTimeNs { + t.Fatalf("Results not sorted in decreasing order of evaluation times") + } + } + } + } +}