From 820c5ce22058e40be35e5328cd6dc9496bbf3fca Mon Sep 17 00:00:00 2001 From: Seebs Date: Fri, 11 Oct 2019 14:20:05 -0500 Subject: [PATCH 1/3] add trivial execution-time profiling What if you could ?profile=true on a query and get some numbers back? That'd be really cool. We already have tracing/spans, but right now, those only generate any data if you have something set up for them to trace to. Add a fancy wrapper that lets us generate our own tracing data, and dump it into the request response, if ?profile=true. We track wall-clock execution time, plus possible arbitrary K/V pairs. Memory stats are not included, because obtaining them is surprisingly expensive. --- api.go | 1 + executor.go | 12 +++++- handler.go | 10 +++++ http/handler.go | 13 ++++++- tracing/tracing.go | 92 +++++++++++++++++++++++++++++++++++++++++++++- 5 files changed, 124 insertions(+), 4 deletions(-) diff --git a/api.go b/api.go index 875d350d6..62002472e 100644 --- a/api.go +++ b/api.go @@ -146,6 +146,7 @@ func (api *API) Query(ctx context.Context, req *QueryRequest) (QueryResponse, er } execOpts := &execOptions{ Remote: req.Remote, + Profile: req.Profile, ExcludeRowAttrs: req.ExcludeRowAttrs, // NOTE: Kept for Pilosa 1.x compat. ExcludeColumns: req.ExcludeColumns, // NOTE: Kept for Pilosa 1.x compat. ColumnAttrs: req.ColumnAttrs, // NOTE: Kept for Pilosa 1.x compat. diff --git a/executor.go b/executor.go index 50ed7f89e..1cb5dcf4e 100644 --- a/executor.go +++ b/executor.go @@ -150,7 +150,16 @@ func (e *executor) Execute(ctx context.Context, index string, q *pql.Query, shar return resp, err } } - + if opt.Profile { + var prof tracing.ProfiledSpan + prof, ctx = tracing.StartProfiledSpanFromContext(ctx, "Execute") + defer prof.Finish() + var ok bool + resp.Profile, ok = prof.(*tracing.Profile) + if !ok { + return resp, fmt.Errorf("profiling execution failed: %T is not tracing.Profile", prof) + } + } results, err := e.execute(ctx, index, q, shards, opt) if err != nil { return resp, err @@ -2959,6 +2968,7 @@ type mapResponse struct { // execOptions represents an execution context for a single Execute() call. type execOptions struct { Remote bool + Profile bool ExcludeRowAttrs bool ExcludeColumns bool ColumnAttrs bool diff --git a/handler.go b/handler.go index f42cf1993..6d1a8fc13 100644 --- a/handler.go +++ b/handler.go @@ -16,6 +16,8 @@ package pilosa import ( "encoding/json" + + "github.com/pilosa/pilosa/v2/tracing" ) // QueryRequest represent a request to process a query. @@ -42,6 +44,9 @@ type QueryRequest struct { // If true, indicates that query is part of a larger distributed query. // If false, this request is on the originating node. Remote bool + + // Should we profile this query? + Profile bool } // QueryResponse represent a response from a processed query. @@ -55,6 +60,9 @@ type QueryResponse struct { // Error during parsing or execution. Err error + + // Profiling data, if any + Profile *tracing.Profile } // MarshalJSON marshals QueryResponse into a JSON-encoded byte slice @@ -68,9 +76,11 @@ func (resp *QueryResponse) MarshalJSON() ([]byte, error) { return json.Marshal(struct { Results []interface{} `json:"results"` ColumnAttrSets []*ColumnAttrSet `json:"columnAttrs,omitempty"` + Profile *tracing.Profile `json:"profile,omitempty"` }{ Results: resp.Results, ColumnAttrSets: resp.ColumnAttrSets, + Profile: resp.Profile, }) } diff --git a/http/handler.go b/http/handler.go index db5d2a326..7e508a43d 100644 --- a/http/handler.go +++ b/http/handler.go @@ -187,7 +187,7 @@ func (h *Handler) populateValidators() { h.validators["DeleteField"] = queryValidationSpecRequired() h.validators["PostImport"] = queryValidationSpecRequired().Optional("clear", "ignoreKeyCheck") h.validators["PostImportRoaring"] = queryValidationSpecRequired().Optional("remote", "clear") - h.validators["PostQuery"] = queryValidationSpecRequired().Optional("shards", "columnAttrs", "excludeRowAttrs", "excludeColumns") + h.validators["PostQuery"] = queryValidationSpecRequired().Optional("shards", "columnAttrs", "excludeRowAttrs", "excludeColumns", "profile") h.validators["GetInfo"] = queryValidationSpecRequired() h.validators["RecalculateCaches"] = queryValidationSpecRequired() h.validators["GetSchema"] = queryValidationSpecRequired() @@ -1021,9 +1021,20 @@ func (h *Handler) readURLQueryRequest(r *http.Request) (*pilosa.QueryRequest, er return nil, errors.New("invalid shard argument") } + // Optional profiling + profile := false + profileString := q.Get("profile") + if profileString != "" { + profile, err = strconv.ParseBool(q.Get("profile")) + if err != nil { + return nil, fmt.Errorf("invalid profile argument: '%s' (should be true/false)", profileString) + } + } + return &pilosa.QueryRequest{ Query: query, Shards: shards, + Profile: profile, ColumnAttrs: q.Get("columnAttrs") == "true", ExcludeRowAttrs: q.Get("excludeRowAttrs") == "true", ExcludeColumns: q.Get("excludeColumns") == "true", diff --git a/tracing/tracing.go b/tracing/tracing.go index 3625166b0..a7d58a251 100644 --- a/tracing/tracing.go +++ b/tracing/tracing.go @@ -17,15 +17,51 @@ package tracing import ( "context" "net/http" + "time" ) // GlobalTracer is a single, global instance of Tracer. var GlobalTracer Tracer = NopTracer() -// StartSpanFromContext returnus a new child span and context from a given +// StartSpanFromContext returns a new child span and context from a given // context using the global tracer. func StartSpanFromContext(ctx context.Context, operationName string) (Span, context.Context) { - return GlobalTracer.StartSpanFromContext(ctx, operationName) + return startMaybeProfiledSpanFromContext(ctx, operationName, false) +} + +// StartProfiledSpanFromContext returns a new child span and context from a given +// context using the global tracer. +func StartProfiledSpanFromContext(ctx context.Context, operationName string) (ProfiledSpan, context.Context) { + span, ctx := startMaybeProfiledSpanFromContext(ctx, operationName, true) + return span.(ProfiledSpan), ctx +} + +// startMaybeProfiledSpanFromContext figures out whether it needs to make a profiling span. +func startMaybeProfiledSpanFromContext(ctx context.Context, operationName string, startProfiling bool) (Span, context.Context) { + var parent ProfiledSpan + makeProfile := startProfiling + // Parent context may or may not be profiled. + // If it is, we need to make a sub-profile. If it isn't, we need to make a new profile if + // startProfiling is set. + span, ok := spanFromContext(ctx) + if ok { + if parent, ok = span.(ProfiledSpan); ok { + makeProfile = true + } + } + // if we aren't making a profile, this is easy: + if !makeProfile { + return GlobalTracer.StartSpanFromContext(ctx, operationName) + } + newProf := &Profile{Name: operationName, Begin: time.Now(), KV: make(map[string]interface{})} + if parent != nil { + parent.AddChild(newProf) + } + inner, ctx := GlobalTracer.StartSpanFromContext(ctx, operationName) + newProf.inner = inner + // insert ourselves in the context + ctx = context.WithValue(ctx, arbitraryContextKey, newProf) + return newProf, ctx } // Tracer implements a generic distributed tracing interface. @@ -49,6 +85,49 @@ type Span interface { LogKV(alternatingKeyValues ...interface{}) } +// ProfiledSpan represents a span which profiles itself and its children. +type ProfiledSpan interface { + Span + Dump() interface{} // suitable for marshaling + AddChild(ProfiledSpan) +} + +// Profile represents the profiling data for a span. It also handles +// the bookkeeping for the underlying span, but this is unexported so +// it doesn't get unmarshaled. +type Profile struct { + inner Span + Name string + Begin, End time.Time `json:"-"` + Duration time.Duration + Children []ProfiledSpan `json:",omitempty"` + KV map[string]interface{} `json:",omitempty"` +} + +func (p *Profile) Finish() { + p.inner.Finish() + p.End = time.Now() + p.Duration = p.End.Sub(p.Begin) +} + +func (p *Profile) LogKV(alternatingKeyValues ...interface{}) { + for i := 0; i < len(alternatingKeyValues)-1; i += 2 { + if s, ok := alternatingKeyValues[i].(string); ok { + p.KV[s] = alternatingKeyValues[i+1] + } + } + p.inner.LogKV(alternatingKeyValues...) +} + +// returns something that json could probably marshal. +func (p *Profile) Dump() interface{} { + return p +} + +func (p *Profile) AddChild(child ProfiledSpan) { + p.Children = append(p.Children, child) +} + // NopTracer returns a tracer that doesn't do anything. func NopTracer() Tracer { return &nopTracer{} @@ -70,3 +149,12 @@ type nopSpan struct{} func (s *nopSpan) Finish() {} func (s *nopSpan) LogKV(alternatingKeyValues ...interface{}) {} + +type arbitraryContextKeyType int + +var arbitraryContextKey arbitraryContextKeyType + +func spanFromContext(ctx context.Context) (Span, bool) { + span, ok := ctx.Value(arbitraryContextKey).(Span) + return span, ok +} From 7a381f7eaf5899296c87650228918219a0302061 Mon Sep 17 00:00:00 2001 From: Seebs Date: Thu, 17 Oct 2019 15:52:54 -0500 Subject: [PATCH 2/3] allow years other than 2017 in licenses Also clean up the license hash checking a bit. We trim vendor early in find so we don't have to walk the whole vendor tree only to grep the files out, and we don't check the license hashes of the exceptions, and the exceptions are now a plain text file of non-regex strings we match exactly. Also the license hash code is only written once. This will help us a lot if development on Pilosa continues through 2018 or later. --- Makefile | 13 ++++++++----- license.exceptions | 9 +++++++++ 2 files changed, 17 insertions(+), 5 deletions(-) create mode 100644 license.exceptions diff --git a/Makefile b/Makefile index 969624d90..f47c92740 100644 --- a/Makefile +++ b/Makefile @@ -16,7 +16,11 @@ RELEASE_ENABLED = $(subst 0,,$(RELEASE)) BUILD_TAGS += $(if $(ENTERPRISE_ENABLED),enterprise) BUILD_TAGS += $(if $(RELEASE_ENABLED),release) BUILD_TAGS += shardwidth$(SHARD_WIDTH) -LICENSE_HASH=$(shell head -13 pilosa.go | shasum | cut -f 1 -d " ") +define LICENSE_HASH_CODE + head -13 $1 | sed -e 's/Copyright 20[0-9][0-9]/Copyright 20XX/g' | shasum | cut -f 1 -d " " +endef +LICENSE_HASH=$(shell $(call LICENSE_HASH_CODE, pilosa.go)) + export GO111MODULE=on # Run tests and compile Pilosa @@ -32,7 +36,7 @@ vendor: go.mod # Run test suite test: - go test ./... -tags='$(BUILD_TAGS)' $(TESTFLAGS) + go test ./... -tags='$(BUILD_TAGS)' $(TESTFLAGS) bench: go test ./... -bench=. -run=NoneZ -timeout=127m $(TESTFLAGS) @@ -161,9 +165,8 @@ gometalinter: require-gometalinter vendor # Verify that all Go files have license header check-license-headers: SHELL:=/bin/bash check-license-headers: - @! find . -name '*.go' | grep -v '^./vendor' | while read fn;\ - do [[ `head -13 $$fn | shasum | cut -f 1 -d " "` == $(LICENSE_HASH) ]] || echo $$fn; done | \ - grep -v apimethod_string.go | grep -v pb.go | grep -v peg.go | grep -v lru.go | grep -v btree | grep -v enterprise + @! find . -path ./vendor -prune -o -name '*.go' -print | grep -v -F -f license.exceptions | while read fn;\ + do [[ `$(call LICENSE_HASH_CODE, $$fn)` == $(LICENSE_HASH) ]] || echo $$fn; done | grep '.' ###################### # Build dependencies # diff --git a/license.exceptions b/license.exceptions new file mode 100644 index 000000000..5d70f2e3a --- /dev/null +++ b/license.exceptions @@ -0,0 +1,9 @@ +# names of files which we do not expect to have our license header +./apimethod_string.go +./pql/pql.peg.go +./internal/private.pb.go +./internal/public.pb.go +./lru/lru.go +./enterprise/enterprise.go +./roaring/btree.go +./roaring/btree_test.go From 616ed39771891223be89f672185cd1b2c37ad38c Mon Sep 17 00:00:00 2001 From: Seebs Date: Fri, 11 Oct 2019 13:59:43 -0500 Subject: [PATCH 3/3] Skip longest tests when running -short The cluster timeout/down tests are way more than half the total time for "go test", and are very unlikely to be of interest in regular usage, although they matter for CI. Skip them when doing short tests. --- cluster_internal_test.go | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/cluster_internal_test.go b/cluster_internal_test.go index 79a28f4ae..dad42d31f 100644 --- a/cluster_internal_test.go +++ b/cluster_internal_test.go @@ -948,6 +948,9 @@ func TestCluster_confirmNodeDownUp(t *testing.T) { } func TestCluster_confirmNodeDownTimeout(t *testing.T) { + if testing.Short() { + t.Skip() + } r := mux.NewRouter() r.HandleFunc("/version", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { time.Sleep(confirmDownSleep * time.Second * confirmDownRetries) @@ -973,10 +976,12 @@ func TestCluster_confirmNodeDownTimeout(t *testing.T) { if !confirmNodeDown(uri, logger.NewVerboseLogger(os.Stdout)) { t.Errorf("expected node to be down") } - } func TestCluster_confirmNodeDownDown(t *testing.T) { + if testing.Short() { + t.Skip() + } uri := URI{} uri.Scheme = "http" uri.Host = "DoesntMatter" @@ -985,5 +990,4 @@ func TestCluster_confirmNodeDownDown(t *testing.T) { if !confirmNodeDown(uri, logger.NewVerboseLogger(os.Stdout)) { t.Errorf("expected node to be down") } - }