From e85546d1b6db62f288a6905ffed759e9592722df Mon Sep 17 00:00:00 2001 From: Ashutosh Narkar Date: Thu, 28 Jun 2018 09:41:25 -0700 Subject: [PATCH] Add Rego profiler Signed-off-by: Ashutosh Narkar --- cover/cover.go | 4 +- profiler/profiler.go | 186 ++++++++++++++++++++++++++++++++++++++ profiler/profiler_test.go | 157 ++++++++++++++++++++++++++++++++ 3 files changed, 345 insertions(+), 2 deletions(-) create mode 100644 profiler/profiler.go create mode 100644 profiler/profiler_test.go diff --git a/cover/cover.go b/cover/cover.go index fad68e2845..90bb862485 100644 --- a/cover/cover.go +++ b/cover/cover.go @@ -104,7 +104,7 @@ type Position struct { Row int `json:"row"` } -// PositionSlice is a collection of positison that can be sorted. +// PositionSlice is a collection of position that can be sorted. type PositionSlice []Position // Sort sorts the slice by line number. @@ -159,7 +159,7 @@ func (fr *FileReport) IsNotCovered(row int) bool { return false } -// Report repreesents a coverage report for a set of files. +// Report represents a coverage report for a set of files. type Report struct { Files map[string]*FileReport `json:"files"` } diff --git a/profiler/profiler.go b/profiler/profiler.go new file mode 100644 index 0000000000..6bd71e7272 --- /dev/null +++ b/profiler/profiler.go @@ -0,0 +1,186 @@ +// Copyright 2018 The OPA Authors. All rights reserved. +// 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 + +import ( + "sort" + "time" + + "github.com/open-policy-agent/opa/ast" + "github.com/open-policy-agent/opa/topdown" +) + +// Profiler computes and reports on the time spent on expressions +type Profiler struct { + hits map[string]map[Position]ExprStats + activeTimer time.Time + prevExpr ExprInfo +} + +// ExprInfo stores information about an expression +type ExprInfo struct { + index int + file string + row int + col int + text []byte + op string +} + +// New returns a new Profiler object +func New() *Profiler { + return &Profiler{ + hits: map[string]map[Position]ExprStats{}, + } +} + +// Enabled returns true if profiler is enabled. +func (p *Profiler) Enabled() bool { + return true +} + +// Report returns a profiler report +func (p *Profiler) Report() (report Report) { + p.processLastExpr() + report.Files = map[string]*FileReport{} + for file, hits := range p.hits { + stats := []ExprStats{} + for _, stat := range hits { + stats = append(stats, stat) + } + + sortStatsByRow(stats) + fr, ok := report.Files[file] + if !ok { + fr = &FileReport{} + report.Files[file] = fr + } + fr.Result = stats + } + return report +} + +// 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") + } + case topdown.RedoOp: + if expr, ok := event.Node.(*ast.Expr); ok && expr != nil { + p.processExpr(expr, "Redo") + } + } +} + +func (p *Profiler) processExpr(expr *ast.Expr, op string) { + + // 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, + } + return + } + + // record the profiler results for the previous expression + hits, ok := p.hits[p.prevExpr.file] + if !ok { + hits = map[Position]ExprStats{} + hits[Position{p.prevExpr.row}] = getProfilerStats(p.prevExpr, p.activeTimer) + p.hits[p.prevExpr.file] = hits + } else { + pStats, ok := hits[Position{p.prevExpr.row}] + if !ok { + hits[Position{p.prevExpr.row}] = getProfilerStats(p.prevExpr, p.activeTimer) + } else { + pStats.TotalTimeNs += time.Since(p.activeTimer).Nanoseconds() + if p.prevExpr.op == "Eval" { + pStats.NumEval++ + } else { + pStats.NumRedo++ + } + hits[Position{p.prevExpr.row}] = 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, + } +} + +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, + } + 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 { + profilerStats := ExprStats{} + profilerStats.TotalTimeNs = time.Since(timer).Nanoseconds() + profilerStats.Index = expr.index + + profilerStats.Row = expr.row + profilerStats.Col = expr.col + profilerStats.Text = string(expr.text) + + if expr.op == "Eval" { + profilerStats.NumEval = 1 + } else { + profilerStats.NumRedo = 1 + } + + return profilerStats +} + +// 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"` +} + +func sortStatsByRow(ps []ExprStats) { + sort.Slice(ps, func(i, j int) bool { + return ps[i].Row < ps[j].Row + }) +} + +// Report represents the profiler report for a set of files. +type Report struct { + Files map[string]*FileReport `json:"files"` +} + +// FileReport represents a profiler report for a single file +type FileReport struct { + Result []ExprStats `json:"result"` +} diff --git a/profiler/profiler_test.go b/profiler/profiler_test.go new file mode 100644 index 0000000000..e3ebc23175 --- /dev/null +++ b/profiler/profiler_test.go @@ -0,0 +1,157 @@ +// Copyright 2018 The OPA Authors. All rights reserved. +// Use of this source code is governed by an Apache2 +// license that can be found in the LICENSE file. + +package profiler + +import ( + "context" + _ "encoding/json" + "testing" + "time" + + "github.com/open-policy-agent/opa/ast" + "github.com/open-policy-agent/opa/rego" + "github.com/open-policy-agent/opa/topdown" + "github.com/open-policy-agent/opa/types" +) + +func TestProfilerLargeArray(t *testing.T) { + profiler := New() + module := `package test + +foo { + bar + not baz + bee +} + +bee { + nums = ["a", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i", "b", "c", "d", "e", "f", "g", "h", "i"] + 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) + } + + report := profiler.Report() + + fr, ok := report.Files["test.rego"] + if !ok { + t.Fatal("Expected file report for test.rego") + } + + if len(fr.Result) != 11 { + t.Fatalf("Expected file report length to be 11 instead got %v", len(fr.Result)) + } +} + +func TestProfileSleepCmd(t *testing.T) { + profiler := New() + + ast.RegisterBuiltin(&ast.Builtin{ + Name: "test.sleep", + Decl: types.NewFunction( + types.Args(types.S), + types.NewNull(), + ), + }) + + topdown.RegisterFunctionalBuiltin1("test.sleep", func(a ast.Value) (ast.Value, error) { + d, _ := time.ParseDuration(string(a.(ast.String))) + time.Sleep(d) + return ast.Null{}, nil + }) + + module := `package test + + foo { + test.sleep("1s") + }` + + _, 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) + } + + report := profiler.Report() + + fr, ok := report.Files["test.rego"] + if !ok { + t.Fatal("Expected file report for test.rego") + } + + if len(fr.Result) != 1 { + 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 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) + } + +}