Merge pull request #12 from seebs/profile

Profiling and a couple of minor fixes

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 #

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.

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")
 	}
-
 }

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

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,
 	})
 }
 

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",

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

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
+}