From eceef6b42bd3d7f13487706270c7f77a47fc8859 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 2 Apr 2020 23:52:50 -0500 Subject: [PATCH 01/26] Use 'query_' prefix to identify query metrics --- executor.go | 27 ++++++++++++++------------- 1 file changed, 14 insertions(+), 13 deletions(-) diff --git a/executor.go b/executor.go index 2c127cc67..b06edcf61 100644 --- a/executor.go +++ b/executor.go @@ -462,7 +462,8 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s } else if err := e.validateCallArgs(c); err != nil { return nil, errors.Wrap(err, "validating args") } - indexTag := fmt.Sprintf("index:%s", index) + indexTag := "index:" + index + metricName := "query_" + c.Name // Fixes #2009 // See: https://github.com/pilosa/pilosa/issues/2009 @@ -487,28 +488,28 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s // Special handling for mutation and top-n calls. if op, ok := e.additionalCountOps[c.Name]; ok { - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeGenericCount(ctx, index, c, op, shards, opt) } if op, ok := e.additionalFieldOps[c.Name]; ok { - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeGenericField(ctx, index, c, op, shards, opt) } switch c.Name { case "Sum": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeSum(ctx, index, c, shards, opt) case "Min": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeMin(ctx, index, c, shards, opt) case "Max": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeMax(ctx, index, c, shards, opt) case "MinRow": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeMinRow(ctx, index, c, shards, opt) case "MaxRow": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeMaxRow(ctx, index, c, shards, opt) case "Clear": return e.executeClearBit(ctx, index, c, opt) @@ -517,7 +518,7 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s case "Store": return e.executeSetRow(ctx, index, c, shards, opt) case "Count": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeCount(ctx, index, c, shards, opt) case "Set": return e.executeSet(ctx, index, c, opt) @@ -526,13 +527,13 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s case "SetColumnAttrs": return nil, e.executeSetColumnAttrs(ctx, index, c, opt) case "TopN": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeTopN(ctx, index, c, shards, opt) case "Rows": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeRows(ctx, index, c, shards, opt) case "GroupBy": - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeGroupBy(ctx, index, c, shards, opt) case "Options": return e.executeOptionsCall(ctx, index, c, shards, opt) @@ -543,7 +544,7 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s case "Precomputed": return e.executePrecomputedCall(ctx, index, c, shards, opt) default: - e.Holder.Stats.CountWithCustomTags(c.Name, 1, 1.0, []string{indexTag}) + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) return e.executeBitmapCall(ctx, index, c, shards, opt) } } From 857ddf73c2d077eb46a5677e39d90340a569e96d Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 2 Apr 2020 23:53:08 -0500 Subject: [PATCH 02/26] Reduce snapshot verbosity --- fragment.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/fragment.go b/fragment.go index c352959ad..f93fc9514 100644 --- a/fragment.go +++ b/fragment.go @@ -2248,7 +2248,7 @@ func (f *fragment) Snapshot() error { func track(start time.Time, message string, stats stats.StatsClient, logger logger.Logger) { elapsed := time.Since(start) - logger.Printf("%s took %s", message, elapsed) + logger.Debugf("%s took %s", message, elapsed) stats.Histogram("snapshot", elapsed.Seconds(), 1.0) } From 84e6a25badc146dc58c147755c5c0540bbd270cb Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 2 Apr 2020 23:53:32 -0500 Subject: [PATCH 03/26] Update help message --- server/server.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/server.go b/server/server.go index 30a8b12de..9d53ddf40 100644 --- a/server/server.go +++ b/server/server.go @@ -453,7 +453,7 @@ func newStatsClient(name string, host string) (stats.StatsClient, error) { case "nop", "none": return stats.NopStatsClient, nil default: - return nil, errors.Errorf("'%v' not a valid stats client, choose from [expvar, statsd, none].", name) + return nil, errors.Errorf("'%v' not a valid stats client, choose from [expvar, statsd, prometheus, none].", name) } } From 70111b560458d2ad01f568c2f33219b1aedffcde Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 01:01:29 -0500 Subject: [PATCH 04/26] Define metrics names as constants --- api.go | 10 +++++----- cache.go | 8 ++++---- executor.go | 12 +++++++----- fragment.go | 26 +++++++++++++------------- holder.go | 12 ++++++------ http/handler.go | 2 +- index.go | 2 +- metrics.go | 48 ++++++++++++++++++++++++++++++++++++++++++++++++ server.go | 20 ++++++++++---------- 9 files changed, 95 insertions(+), 45 deletions(-) create mode 100644 metrics.go diff --git a/api.go b/api.go index 35366ac4c..7ced231ae 100644 --- a/api.go +++ b/api.go @@ -185,7 +185,7 @@ func (api *API) CreateIndex(ctx context.Context, indexName string, options Index if err != nil { return nil, errors.Wrap(err, "sending CreateIndex message") } - api.holder.Stats.Count("createIndex", 1, 1.0) + api.holder.Stats.Count(MetricCreateIndex, 1, 1.0) return index, nil } @@ -229,7 +229,7 @@ func (api *API) DeleteIndex(ctx context.Context, indexName string) error { api.server.logger.Printf("problem sending DeleteIndex message: %s", err) return errors.Wrap(err, "sending DeleteIndex message") } - api.holder.Stats.Count("deleteIndex", 1, 1.0) + api.holder.Stats.Count(MetricDeleteIndex, 1, 1.0) return nil } @@ -276,7 +276,7 @@ func (api *API) CreateField(ctx context.Context, indexName string, fieldName str api.server.logger.Printf("problem sending CreateField message: %s", err) return nil, errors.Wrap(err, "sending CreateField message") } - api.holder.Stats.CountWithCustomTags("createField", 1, 1.0, []string{fmt.Sprintf("index:%s", indexName)}) + api.holder.Stats.CountWithCustomTags(MetricCreateField, 1, 1.0, []string{fmt.Sprintf("index:%s", indexName)}) return field, nil } @@ -487,7 +487,7 @@ func (api *API) DeleteField(ctx context.Context, indexName string, fieldName str api.server.logger.Printf("problem sending DeleteField message: %s", err) return errors.Wrap(err, "sending DeleteField message") } - api.holder.Stats.CountWithCustomTags("deleteField", 1, 1.0, []string{fmt.Sprintf("index:%s", indexName)}) + api.holder.Stats.CountWithCustomTags(MetricDeleteField, 1, 1.0, []string{fmt.Sprintf("index:%s", indexName)}) return nil } @@ -519,7 +519,7 @@ func (api *API) DeleteAvailableShard(_ context.Context, indexName, fieldName str api.server.logger.Printf("problem sending DeleteAvailableShard message: %s", err) return errors.Wrap(err, "sending DeleteAvailableShard message") } - api.holder.Stats.CountWithCustomTags("deleteAvailableShard", 1, 1.0, []string{fmt.Sprintf("index:%s", indexName)}) + api.holder.Stats.CountWithCustomTags(MetricDeleteAvailableShard, 1, 1.0, []string{fmt.Sprintf("index:%s", indexName)}) return nil } diff --git a/cache.go b/cache.go index e48c9cf17..99a13640e 100644 --- a/cache.go +++ b/cache.go @@ -231,7 +231,7 @@ func (c *rankCache) Invalidate() { func (c *rankCache) Recalculate() { c.mu.Lock() defer c.mu.Unlock() - c.stats.Count("cache.recalculate", 1, 1.0) + c.stats.Count(MetricRecalculateCache, 1, 1.0) c.recalculate() } @@ -241,7 +241,7 @@ func (c *rankCache) invalidate() { if time.Since(c.updateTime).Seconds() < 10 { return } - c.stats.Count("cache.invalidate", 1, 1.0) + c.stats.Count(MetricInvalidateCache, 1, 1.0) c.recalculate() } @@ -259,7 +259,7 @@ func (c *rankCache) recalculate() { // Store the count of the item at the threshold index. c.rankings = rankings length := len(c.rankings) - c.stats.Gauge("RankCache", float64(length), 1.0) + c.stats.Gauge(MetricRankCacheLength, float64(length), 1.0) var removeItems []bitmapPair // cached, ordered list if length > int(c.maxEntries) { @@ -275,7 +275,7 @@ func (c *rankCache) recalculate() { // If size is larger than the threshold then trim it. if len(c.entries) > c.thresholdBuffer { - c.stats.Count("cache.threshold", 1, 1.0) + c.stats.Count(MetricCacheThresholdReached, 1, 1.0) for _, pair := range removeItems { delete(c.entries, pair.ID) } diff --git a/executor.go b/executor.go index b06edcf61..58446c81f 100644 --- a/executor.go +++ b/executor.go @@ -2229,7 +2229,7 @@ func (e *executor) executeRowShard(ctx context.Context, index string, c *pql.Cal return rows[0], nil } row := rows[0].Union(rows[1:]...) - f.Stats.Count("range", 1, 1.0) + f.Stats.Count(MetricRow, 1, 1.0) return row, nil } @@ -2283,6 +2283,7 @@ func (e *executor) executeRowBSIGroupShard(ctx context.Context, index string, c return NewRow(), nil } + f.Stats.Count(MetricRowBSI, 1, 1.0) return frag.notNull() } else if cond.Op == pql.BETWEEN || cond.Op == pql.BTWN_LT_LT || @@ -2324,6 +2325,7 @@ func (e *executor) executeRowBSIGroupShard(ctx context.Context, index string, c return frag.notNull() } + f.Stats.Count(MetricRowBSI, 1, 1.0) return frag.rangeBetween(bsig.BitDepth, baseValueMin, baseValueMax) } else { @@ -2360,7 +2362,7 @@ func (e *executor) executeRowBSIGroupShard(ctx context.Context, index string, c return frag.notNull() } - f.Stats.Count("range:bsigroup", 1, 1.0) + f.Stats.Count(MetricRowBSI, 1, 1.0) return frag.rangeOp(cond.Op, bsig.BitDepth, baseValue) } } @@ -3103,7 +3105,7 @@ func (e *executor) executeSetRowAttrs(ctx context.Context, index string, c *pql. if err := field.RowAttrStore().SetAttrs(rowID, attrs); err != nil { return err } - field.Stats.Count("SetRowAttrs", 1, 1.0) + field.Stats.Count(MetricSetRowAttrs, 1, 1.0) // Do not forward call if this is already being forwarded. if opt.Remote { @@ -3197,7 +3199,7 @@ func (e *executor) executeBulkSetRowAttrs(ctx context.Context, index string, cal if err := field.RowAttrStore().SetBulkAttrs(fieldMap); err != nil { return nil, err } - field.Stats.Count("SetRowAttrs", 1, 1.0) + field.Stats.Count(MetricSetRowAttrs, 1, 1.0) } // Do not forward call if this is already being forwarded. @@ -3251,7 +3253,7 @@ func (e *executor) executeSetColumnAttrs(ctx context.Context, index string, c *p if err := idx.ColumnAttrStore().SetAttrs(col, attrs); err != nil { return err } - idx.Stats.Count("SetProfileAttrs", 1, 1.0) + idx.Stats.Count(MetricSetProfileAttrs, 1, 1.0) // Do not forward call if this is already being forwarded. if opt.Remote { return nil diff --git a/fragment.go b/fragment.go index f93fc9514..57d4dd820 100644 --- a/fragment.go +++ b/fragment.go @@ -208,7 +208,7 @@ func (f *fragment) Open() error { // Read last bit to determine max row. f.maxRowID = f.storage.Max() / ShardWidth - f.stats.Gauge("rows", float64(f.maxRowID), 1.0) + f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) return nil }(); err != nil { f.close() @@ -576,12 +576,12 @@ func (f *fragment) unprotectedSetBit(rowID, columnID uint64) (changed bool, err // a new copy if no one's reading it. f.rowCache.Add(rowID, nil) - f.stats.Count("setBit", 1, 0.001) + f.stats.Count(MetricSetBit, 1, 0.001) // Update row count if they have increased. if rowID > f.maxRowID { f.maxRowID = rowID - f.stats.Gauge("rows", float64(f.maxRowID), 1.0) + f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) } return changed, nil @@ -635,7 +635,7 @@ func (f *fragment) unprotectedClearBit(rowID, columnID uint64) (changed bool, er // a new copy if no one's reading it. f.rowCache.Add(rowID, nil) - f.stats.Count("clearBit", 1, 1.0) + f.stats.Count(MetricClearBit, 1, 1.0) return changed, nil } @@ -691,7 +691,7 @@ func (f *fragment) unprotectedSetRow(row *Row, rowID uint64) (changed bool, err // Snapshot storage. f.snapshotQueue.Enqueue(f) - f.stats.Count("setRow", 1, 1.0) + f.stats.Count(MetricSetRow, 1, 1.0) return changed, nil } @@ -733,7 +733,7 @@ func (f *fragment) unprotectedClearRow(rowID uint64) (changed bool, err error) { // Snapshot storage. f.snapshotQueue.Enqueue(f) - f.stats.Count("clearRow", 1, 1.0) + f.stats.Count(MetricClearRow, 1, 1.0) return changed, nil } @@ -1945,22 +1945,22 @@ func (f *fragment) bulkImportStandard(rowIDs, columnIDs []uint64, options *Impor func (f *fragment) importPositions(set, clear []uint64, rowSet map[uint64]struct{}) error { err := f.gen.Transaction(&f.storage.OpWriter, func() error { if len(set) > 0 { - f.stats.Count("ImportingN", int64(len(set)), 1) + f.stats.Count(MetricImportingN, int64(len(set)), 1) changedN, err := f.storage.AddN(set...) // TODO benchmark Add/RemoveN behavior with sorted/unsorted positions if err != nil { return errors.Wrap(err, "adding positions") } - f.stats.Count("ImportedN", int64(changedN), 1) + f.stats.Count(MetricImportedN, int64(changedN), 1) f.incrementOpN(changedN) } if len(clear) > 0 { - f.stats.Count("ClearingN", int64(len(clear)), 1) + f.stats.Count(MetricClearingN, int64(len(clear)), 1) changedN, err := f.storage.RemoveN(clear...) if err != nil { return errors.Wrap(err, "clearing positions") } - f.stats.Count("ClearedN", int64(changedN), 1) + f.stats.Count(MetricClearedN, int64(changedN), 1) f.incrementOpN(changedN) } @@ -2249,7 +2249,7 @@ func (f *fragment) Snapshot() error { func track(start time.Time, message string, stats stats.StatsClient, logger logger.Logger) { elapsed := time.Since(start) logger.Debugf("%s took %s", message, elapsed) - stats.Histogram("snapshot", elapsed.Seconds(), 1.0) + stats.Histogram(MetricSnapshot, elapsed.Seconds(), 1.0) } // snapshot does the actual snapshot operation. it does not check or care @@ -3044,13 +3044,13 @@ func (s *fragmentSyncer) syncFragment() error { if err := s.syncBlockFromPrimary(blockID); err != nil { return fmt.Errorf("sync block from primary: id=%d, err=%s", blockID, err) } - s.Fragment.stats.Count("BlockRepairPrimary", 1, 1.0) + s.Fragment.stats.Count(MetricBlockRepairPrimary, 1, 1.0) default: // Synchronize block. if err := s.syncBlock(blockID); err != nil { return fmt.Errorf("sync block: id=%d, err=%s", blockID, err) } - s.Fragment.stats.Count("BlockRepair", 1, 1.0) + s.Fragment.stats.Count(MetricBlockRepair, 1, 1.0) } } diff --git a/holder.go b/holder.go index 3b9631761..6ba6d5967 100644 --- a/holder.go +++ b/holder.go @@ -801,10 +801,10 @@ func (s *holderSyncer) SyncHolder() error { } } } - s.Stats.Histogram("syncField", float64(time.Since(tf)), 1.0) + s.Stats.Histogram(MetricSyncField, float64(time.Since(tf)), 1.0) tf = time.Now() // reset tf } - s.Stats.Histogram("syncIndex", float64(time.Since(ti)), 1.0) + s.Stats.Histogram(MetricSyncIndex, float64(time.Since(ti)), 1.0) ti = time.Now() // reset ti } @@ -828,7 +828,7 @@ func (s *holderSyncer) syncIndex(index string) error { if err != nil { return errors.Wrap(err, "getting blocks") } - s.Stats.CountWithCustomTags("ColumnAttrStoreBlocks", int64(len(blks)), 1.0, []string{indexTag}) + s.Stats.CountWithCustomTags(MetricColumnAttrStoreBlocks, int64(len(blks)), 1.0, []string{indexTag}) // Sync with every other host. for _, node := range Nodes(s.Cluster.nodes).FilterID(s.Node.ID) { @@ -840,7 +840,7 @@ func (s *holderSyncer) syncIndex(index string) error { } else if len(m) == 0 { continue } - s.Stats.CountWithCustomTags("ColumnAttrDiff", int64(len(m)), 1.0, []string{indexTag, node.ID}) + s.Stats.CountWithCustomTags(MetricColumnAttrDiff, int64(len(m)), 1.0, []string{indexTag, node.ID}) // Update local copy. if err := idx.ColumnAttrStore().SetBulkAttrs(m); err != nil { @@ -875,7 +875,7 @@ func (s *holderSyncer) syncField(index, name string) error { if err != nil { return errors.Wrap(err, "getting blocks") } - s.Stats.CountWithCustomTags("RowAttrStoreBlocks", int64(len(blks)), 1.0, []string{indexTag, fieldTag}) + s.Stats.CountWithCustomTags(MetricRowAttrStoreBlocks, int64(len(blks)), 1.0, []string{indexTag, fieldTag}) // Sync with every other host. for _, node := range Nodes(s.Cluster.nodes).FilterID(s.Node.ID) { @@ -889,7 +889,7 @@ func (s *holderSyncer) syncField(index, name string) error { } else if len(m) == 0 { continue } - s.Stats.CountWithCustomTags("RowAttrDiff", int64(len(m)), 1.0, []string{indexTag, fieldTag, node.ID}) + s.Stats.CountWithCustomTags(MetricRowAttrDiff, int64(len(m)), 1.0, []string{indexTag, fieldTag, node.ID}) // Update local copy. if err := f.RowAttrStore().SetBulkAttrs(m); err != nil { diff --git a/http/handler.go b/http/handler.go index cac26487c..c8faf46a0 100644 --- a/http/handler.go +++ b/http/handler.go @@ -296,7 +296,7 @@ func (h *Handler) collectStats(next http.Handler) http.Handler { stats := h.api.StatsWithTags(statsTags) if stats != nil { - stats.Timing("http.request", dur, 0.1) + stats.Timing(MetricHttpRequest, dur, 0.1) } }) } diff --git a/index.go b/index.go index a5b6245ba..a5f143bfc 100644 --- a/index.go +++ b/index.go @@ -350,7 +350,7 @@ func (i *Index) AvailableShards() *roaring.Bitmap { b.UnionInPlace(f.AvailableShards()) } - i.Stats.Gauge("maxShard", float64(b.Max()), 1.0) + i.Stats.Gauge(MetricMaxShard, float64(b.Max()), 1.0) return b } diff --git a/metrics.go b/metrics.go new file mode 100644 index 000000000..40005bdb0 --- /dev/null +++ b/metrics.go @@ -0,0 +1,48 @@ +package pilosa + +const ( + MetricCreateIndex = "createIndex" + MetricDeleteIndex = "deleteIndex" + MetricCreateField = "createField" + MetricDeleteField = "deleteField" + MetricDeleteAvailableShard = "deleteAvailableShard" + MetricRecalculateCache = "cache.recalculate" + MetricInvalidateCache = "cache.invalidate" + MetricRankCacheLength = "RankCache" + MetricCacheThresholdReached = "cache.threshold" + MetricRow = "range" + MetricRowBSI = "range:bsigroup" + MetricSetRowAttrs = "SetRowAttrs" + MetricSetProfileAttrs = "SetProfileAttrs" + MetricMaximumRow = "maximum_row" + MetricSetBit = "setBit" + MetricRows = "rows" + MetricClearBit = "clearBit" + MetricSetRow = "setRow" + MetricClearRow = "clearRow" + MetricImportingN = "ImportingN" + MetricImportedN = "ImportedN" + MetricClearingN = "ClearingN" + MetricClearedN = "ClearedN" + MetricSnapshot = "snapshot" + MetricBlockRepairPrimary = "BlockRepairPrimary" + MetricBlockRepair = "BlockRepair" + MetricSyncField = "syncField" + MetricSyncIndex = "syncIndex" + MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" + MetricColumnAttrDiff = "ColumnAttrDiff" + MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" + MetricRowAttrDiff = "RowAttrDiff" + MetricHttpRequest = "http.request" + MetricMaxShard = "maxShard" + MetricAntiEntropy = "AntiEntropy" + MetricAntiEntropyDuration = "AntiEntropyDuration" + MetricGarbageCollection = "garbage_collection" + MetricGoroutines = "goroutines" + MetricOpenFiles = "OpenFiles" + MetricHeapAlloc = "HeapAlloc" + MetricHeapInuse = "HeapInuse" + MetricStackInuse = "StackInuse" + MetricMallocs = "Mallocs" + MetricFrees = "Frees" +) diff --git a/server.go b/server.go index cecc520e4..810947b47 100644 --- a/server.go +++ b/server.go @@ -654,7 +654,7 @@ func (s *Server) monitorAntiEntropy() { case <-s.cluster.abortAntiEntropyCh: // receive here so we don't block resizing continue case <-ticker.C: - s.holder.Stats.Count("AntiEntropy", 1, 1.0) + s.holder.Stats.Count(MetricAntiEntropy, 1, 1.0) } t := time.Now() if s.cluster.State() == ClusterStateResizing { @@ -675,7 +675,7 @@ func (s *Server) monitorAntiEntropy() { // Record successful sync in log. s.logger.Printf("holder sync complete") dif := time.Since(t) - s.holder.Stats.Histogram("AntiEntropyDuration", float64(dif), 1.0) + s.holder.Stats.Histogram(MetricAntiEntropyDuration, float64(dif), 1.0) // Drain tick channel since we just finished anti-entropy. If the AE // process took a long time, we don't want them to pile up on each @@ -957,26 +957,26 @@ func (s *Server) monitorRuntime() { return case <-s.gcNotifier.AfterGC(): // GC just ran. - s.holder.Stats.Count("garbage_collection", 1, 1.0) + s.holder.Stats.Count(MetricGarbageCollection, 1, 1.0) case <-ticker.C: } // Record the number of go routines. - s.holder.Stats.Gauge("goroutines", float64(runtime.NumGoroutine()), 1.0) + s.holder.Stats.Gauge(MetricGoroutines, float64(runtime.NumGoroutine()), 1.0) openFiles, err := countOpenFiles() // Open File handles. if err == nil { - s.holder.Stats.Gauge("OpenFiles", float64(openFiles), 1.0) + s.holder.Stats.Gauge(MetricOpenFiles, float64(openFiles), 1.0) } // Runtime memory metrics. runtime.ReadMemStats(&m) - s.holder.Stats.Gauge("HeapAlloc", float64(m.HeapAlloc), 1.0) - s.holder.Stats.Gauge("HeapInuse", float64(m.HeapInuse), 1.0) - s.holder.Stats.Gauge("StackInuse", float64(m.StackInuse), 1.0) - s.holder.Stats.Gauge("Mallocs", float64(m.Mallocs), 1.0) - s.holder.Stats.Gauge("Frees", float64(m.Frees), 1.0) + s.holder.Stats.Gauge(MetricHeapAlloc, float64(m.HeapAlloc), 1.0) + s.holder.Stats.Gauge(MetricHeapInuse, float64(m.HeapInuse), 1.0) + s.holder.Stats.Gauge(MetricStackInuse, float64(m.StackInuse), 1.0) + s.holder.Stats.Gauge(MetricMallocs, float64(m.Mallocs), 1.0) + s.holder.Stats.Gauge(MetricFrees, float64(m.Frees), 1.0) } } From b1adcd91fc8f47ee02ddd11beb5d6e33feb51690 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 01:04:11 -0500 Subject: [PATCH 05/26] Use consistent metric name convention --- fragment.go | 2 +- holder.go | 4 +-- metrics.go | 75 ++++++++++++++++++++++++++--------------------------- 3 files changed, 40 insertions(+), 41 deletions(-) diff --git a/fragment.go b/fragment.go index 57d4dd820..588ea77ae 100644 --- a/fragment.go +++ b/fragment.go @@ -2249,7 +2249,7 @@ func (f *fragment) Snapshot() error { func track(start time.Time, message string, stats stats.StatsClient, logger logger.Logger) { elapsed := time.Since(start) logger.Debugf("%s took %s", message, elapsed) - stats.Histogram(MetricSnapshot, elapsed.Seconds(), 1.0) + stats.Histogram(MetricSnapshotDuration, elapsed.Seconds(), 1.0) } // snapshot does the actual snapshot operation. it does not check or care diff --git a/holder.go b/holder.go index 6ba6d5967..8ae7a32dc 100644 --- a/holder.go +++ b/holder.go @@ -801,10 +801,10 @@ func (s *holderSyncer) SyncHolder() error { } } } - s.Stats.Histogram(MetricSyncField, float64(time.Since(tf)), 1.0) + s.Stats.Histogram(MetricSyncFieldDuration, float64(time.Since(tf)), 1.0) tf = time.Now() // reset tf } - s.Stats.Histogram(MetricSyncIndex, float64(time.Since(ti)), 1.0) + s.Stats.Histogram(MetricSyncIndexDuration, float64(time.Since(ti)), 1.0) ti = time.Now() // reset ti } diff --git a/metrics.go b/metrics.go index 40005bdb0..fcbf31cc5 100644 --- a/metrics.go +++ b/metrics.go @@ -1,48 +1,47 @@ package pilosa const ( - MetricCreateIndex = "createIndex" - MetricDeleteIndex = "deleteIndex" - MetricCreateField = "createField" - MetricDeleteField = "deleteField" - MetricDeleteAvailableShard = "deleteAvailableShard" - MetricRecalculateCache = "cache.recalculate" - MetricInvalidateCache = "cache.invalidate" - MetricRankCacheLength = "RankCache" - MetricCacheThresholdReached = "cache.threshold" - MetricRow = "range" - MetricRowBSI = "range:bsigroup" - MetricSetRowAttrs = "SetRowAttrs" - MetricSetProfileAttrs = "SetProfileAttrs" + MetricCreateIndex = "create_index_total" + MetricDeleteIndex = "delete_index_total" + MetricCreateField = "create_field_total" + MetricDeleteField = "delete_field_total" + MetricDeleteAvailableShard = "delete_available_shard_total" + MetricRecalculateCache = "recalculate_cache_total" + MetricInvalidateCache = "invalidate_cache_total" + MetricRankCacheLength = "rank_cache_length" + MetricCacheThresholdReached = "cache_threshold_reached_total" + MetricRow = "query_row_total" + MetricRowBSI = "query_row_bsi_total" + MetricSetRowAttrs = "query_set_row_attrs_total" + MetricSetProfileAttrs = "query_set_profile_attrs_total" MetricMaximumRow = "maximum_row" - MetricSetBit = "setBit" - MetricRows = "rows" - MetricClearBit = "clearBit" - MetricSetRow = "setRow" - MetricClearRow = "clearRow" - MetricImportingN = "ImportingN" - MetricImportedN = "ImportedN" - MetricClearingN = "ClearingN" - MetricClearedN = "ClearedN" - MetricSnapshot = "snapshot" - MetricBlockRepairPrimary = "BlockRepairPrimary" - MetricBlockRepair = "BlockRepair" - MetricSyncField = "syncField" - MetricSyncIndex = "syncIndex" + MetricSetBit = "set_bit_total" + MetricClearBit = "clear_bit_total" + MetricSetRow = "set_row_total" + MetricClearRow = "clear_row_total" + MetricImportingN = "importing_total" + MetricImportedN = "imported_total" + MetricClearingN = "clearing_total" + MetricClearedN = "cleared_total" + MetricSnapshotDuration = "snapshot_duration_seconds" + MetricBlockRepairPrimary = "block_repair_primary_total" + MetricBlockRepair = "block_repair_total" + MetricSyncFieldDuration = "sync_field_duration_seconds" + MetricSyncIndexDuration = "sync_index_duration_seconds" MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" MetricColumnAttrDiff = "ColumnAttrDiff" MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" MetricRowAttrDiff = "RowAttrDiff" - MetricHttpRequest = "http.request" - MetricMaxShard = "maxShard" - MetricAntiEntropy = "AntiEntropy" - MetricAntiEntropyDuration = "AntiEntropyDuration" - MetricGarbageCollection = "garbage_collection" + MetricHttpRequest = "http_request_total" + MetricMaxShard = "maximum_shard" + MetricAntiEntropy = "antientropy_total" + MetricAntiEntropyDuration = "antientropy_duration_seconds" + MetricGarbageCollection = "garbage_collection_total" MetricGoroutines = "goroutines" - MetricOpenFiles = "OpenFiles" - MetricHeapAlloc = "HeapAlloc" - MetricHeapInuse = "HeapInuse" - MetricStackInuse = "StackInuse" - MetricMallocs = "Mallocs" - MetricFrees = "Frees" + MetricOpenFiles = "open_files" + MetricHeapAlloc = "heap_alloc" + MetricHeapInuse = "heap_inuse" + MetricStackInuse = "stack_inuse" + MetricMallocs = "mallocs" + MetricFrees = "frees" ) From 3c275681d2bfb16783be82641cde82c8b2e5c846 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 01:06:06 -0500 Subject: [PATCH 06/26] Profile -> Column --- executor.go | 2 +- metrics.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/executor.go b/executor.go index 58446c81f..d5bd70483 100644 --- a/executor.go +++ b/executor.go @@ -3253,7 +3253,7 @@ func (e *executor) executeSetColumnAttrs(ctx context.Context, index string, c *p if err := idx.ColumnAttrStore().SetAttrs(col, attrs); err != nil { return err } - idx.Stats.Count(MetricSetProfileAttrs, 1, 1.0) + idx.Stats.Count(MetricSetColumnAttrs, 1, 1.0) // Do not forward call if this is already being forwarded. if opt.Remote { return nil diff --git a/metrics.go b/metrics.go index fcbf31cc5..cc39d32e8 100644 --- a/metrics.go +++ b/metrics.go @@ -13,7 +13,7 @@ const ( MetricRow = "query_row_total" MetricRowBSI = "query_row_bsi_total" MetricSetRowAttrs = "query_set_row_attrs_total" - MetricSetProfileAttrs = "query_set_profile_attrs_total" + MetricSetColumnAttrs = "query_set_column_attrs_total" MetricMaximumRow = "maximum_row" MetricSetBit = "set_bit_total" MetricClearBit = "clear_bit_total" From 34c6d42063dc3a242051ae5f9e2336cbd2121835 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 01:07:33 -0500 Subject: [PATCH 07/26] Fix broken metrics label and log when others are encountered --- prometheus/prometheus.go | 5 +++-- server.go | 2 +- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index 2057bde3a..3cebb0c32 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -94,7 +94,7 @@ func (c *prometheusClient) Tags() []string { // labels returns an instance of prometheus.Labels with the value of the set tags. func (c *prometheusClient) labels() prometheus.Labels { - return tagsToLabels(c.tags) + return tagsToLabels(c.tags, c.logger) } // WithTags returns a new client with additional tags appended. @@ -296,12 +296,13 @@ func unionStringSlice(a, b []string) []string { return other } -func tagsToLabels(tags []string) (labels prometheus.Labels) { +func tagsToLabels(tags []string, logger logger.Logger) (labels prometheus.Labels) { labels = make(prometheus.Labels) for _, tag := range tags { tagParts := strings.SplitAfterN(tag, ":", 2) if len(tagParts) != 2 { // only process tags in "key:value" form + logger.Debugf("Invalid Prometheus label: %v\n", tag) continue } labels[tagParts[0][0:len(tagParts[0])-1]] = tagParts[1] diff --git a/server.go b/server.go index 810947b47..9c11d216f 100644 --- a/server.go +++ b/server.go @@ -517,7 +517,7 @@ func (s *Server) Open() error { s.syncer.Node = s.cluster.Node s.syncer.Cluster = s.cluster s.syncer.Closing = s.closing - s.syncer.Stats = s.holder.Stats.WithTags("HolderSyncer") + s.syncer.Stats = s.holder.Stats.WithTags("component:HolderSyncer") // Start background process listening for translation // sync resets. From 5137f56f9c63c236bdd8fa1a46fe4a7225f20a79 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 01:26:02 -0500 Subject: [PATCH 08/26] Use const from package --- http/handler.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/http/handler.go b/http/handler.go index c8faf46a0..6cb5a08c5 100644 --- a/http/handler.go +++ b/http/handler.go @@ -296,7 +296,7 @@ func (h *Handler) collectStats(next http.Handler) http.Handler { stats := h.api.StatsWithTags(statsTags) if stats != nil { - stats.Timing(MetricHttpRequest, dur, 0.1) + stats.Timing(pilosa.MetricHttpRequest, dur, 0.1) } }) } From 8c9db373d0e112e3f55ce4e79d19ffdd40e9d36d Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 12:10:27 -0500 Subject: [PATCH 09/26] Fix some metrics names --- executor.go | 2 +- metrics.go | 18 ++++++++++++++++-- prometheus/prometheus.go | 4 ++-- stats/stats_test.go | 32 ++++++++++++++++---------------- 4 files changed, 35 insertions(+), 21 deletions(-) diff --git a/executor.go b/executor.go index d5bd70483..daf3f1320 100644 --- a/executor.go +++ b/executor.go @@ -463,7 +463,7 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s return nil, errors.Wrap(err, "validating args") } indexTag := "index:" + index - metricName := "query_" + c.Name + metricName := "query_" + strings.ToLower(c.Name) + "_total" // Fixes #2009 // See: https://github.com/pilosa/pilosa/issues/2009 diff --git a/metrics.go b/metrics.go index cc39d32e8..fc451772f 100644 --- a/metrics.go +++ b/metrics.go @@ -1,3 +1,17 @@ +// Copyright 2020 Pilosa Corp. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + package pilosa const ( @@ -12,8 +26,8 @@ const ( MetricCacheThresholdReached = "cache_threshold_reached_total" MetricRow = "query_row_total" MetricRowBSI = "query_row_bsi_total" - MetricSetRowAttrs = "query_set_row_attrs_total" - MetricSetColumnAttrs = "query_set_column_attrs_total" + MetricSetRowAttrs = "query_setrowattrs_total" + MetricSetColumnAttrs = "query_setcolumnattrs_total" MetricMaximumRow = "maximum_row" MetricSetBit = "set_bit_total" MetricClearBit = "clear_bit_total" diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index 3cebb0c32..4208e29a5 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -252,8 +252,8 @@ func (c *prometheusClient) Set(name string, value string, rate float64) { // Timing tracks timing information for a metric. func (c *prometheusClient) Timing(name string, value time.Duration, rate float64) { - durationMs := value / time.Second - c.Histogram(name, float64(durationMs), rate) + durationS := value / time.Second + c.Histogram(name, float64(durationS), rate) } // SetLogger sets the logger for client. diff --git a/stats/stats_test.go b/stats/stats_test.go index 5c730bf97..a710cd08d 100644 --- a/stats/stats_test.go +++ b/stats/stats_test.go @@ -101,8 +101,8 @@ func TestStatsCount_TopN(t *testing.T) { called := false hldr.Holder.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, tags []string) { - if name != "TopN" { - t.Errorf("Expected TopN, Results %s", name) + if name != "query_topn_total" { + t.Errorf("Expected query_topn_total, Results %s", name) } if tags[0] != "index:d" { @@ -130,8 +130,8 @@ func TestStatsCount_Bitmap(t *testing.T) { called := false hldr.Holder.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, tags []string) { - if name != "Row" { - t.Errorf("Expected Row, Results %s", name) + if name != "query_row_total" { + t.Errorf("Expected query_row_total, Results %s", name) } if tags[0] != "index:d" { @@ -165,8 +165,8 @@ func TestStatsCount_SetColumnAttrs(t *testing.T) { field.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "SetRowAttrs" { - t.Errorf("Expected SetRowAttrs, Results %s", name) + if name != "query_setrowattrs_total" { + t.Errorf("Expected query_setrowattrs_total, Results %s", name) } called = true }, @@ -195,8 +195,8 @@ func TestStatsCount_SetProfileAttrs(t *testing.T) { idx.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "SetProfileAttrs" { - t.Errorf("Expected SetProfilepAttrs, Results %s", name) + if name != "query_setcolumnattrs_total" { + t.Errorf("Expected query_setcolumnattrs_total, Results %s", name) } called = true @@ -222,8 +222,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "createIndex" { - t.Errorf("Expected createIndex, Results %s", name) + if name != "create_index_total" { + t.Errorf("Expected create_index_total, Results %s", name) } called = true }, @@ -239,8 +239,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, index []string) { - if name != "createField" { - t.Errorf("Expected createField, Results %s", name) + if name != "create_field_total" { + t.Errorf("Expected create_field_total, Results %s", name) } if index[0] != "index:i" { t.Errorf("Expected index:i, Results %s", index) @@ -260,8 +260,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, index []string) { - if name != "deleteField" { - t.Errorf("Expected deleteField, Results %s", name) + if name != "delete_field_total" { + t.Errorf("Expected delete_field_total, Results %s", name) } if index[0] != "index:i" { t.Errorf("Expected index:i, Results %s", index) @@ -281,8 +281,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "deleteIndex" { - t.Errorf("Expected deleteIndex, Results %s", name) + if name != "delete_index_total" { + t.Errorf("Expected delete_index_total, Results %s", name) } called = true From a3fb1c022be24680e412c0d38d2b7b60ec75d014 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 3 Apr 2020 12:50:36 -0500 Subject: [PATCH 10/26] Use metrics consts in tests --- stats/stats_test.go | 43 +++++++++++++++++++++++-------------------- 1 file changed, 23 insertions(+), 20 deletions(-) diff --git a/stats/stats_test.go b/stats/stats_test.go index a710cd08d..8ac3606c2 100644 --- a/stats/stats_test.go +++ b/stats/stats_test.go @@ -16,6 +16,7 @@ package stats_test import ( "context" + "fmt" "net/http/httptest" "strings" "testing" @@ -45,39 +46,41 @@ func TestMultiStatClient_Expvar(t *testing.T) { hldr.SetBit("d", "f", 0, pilosa.ShardWidth+2) hldr.ClearBit("d", "f", 0, 1) - if stats.Expvar.String() != `{"index:d": {"clearBit": 1, "rows": 0, "setBit": 4}}` { + indexStats := fmt.Sprintf(`{"%s": %d, "%s": %d, "%s": %d}`, pilosa.MetricClearBit, 1, pilosa.MetricMaximumRow, 0, pilosa.MetricSetBit, 4) + + if stats.Expvar.String() != `{"index:d": `+indexStats+`}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) } hldr.Stats.CountWithCustomTags("cc", 1, 1.0, []string{"foo:bar"}) - if stats.Expvar.String() != `{"cc": 1, "index:d": {"clearBit": 1, "rows": 0, "setBit": 4}}` { + if stats.Expvar.String() != `{"cc": 1, "index:d": `+indexStats+`}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) } // Gauge creates a unique key, subsequent Gauge calls will overwrite hldr.Stats.Gauge("g", 5, 1.0) hldr.Stats.Gauge("g", 8, 1.0) - if stats.Expvar.String() != `{"cc": 1, "g": 8, "index:d": {"clearBit": 1, "rows": 0, "setBit": 4}}` { + if stats.Expvar.String() != `{"cc": 1, "g": 8, "index:d": `+indexStats+`}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) } // Set creates a unique key, subsequent sets will overwrite hldr.Stats.Set("s", "4", 1.0) hldr.Stats.Set("s", "7", 1.0) - if stats.Expvar.String() != `{"cc": 1, "g": 8, "index:d": {"clearBit": 1, "rows": 0, "setBit": 4}, "s": "7"}` { + if stats.Expvar.String() != `{"cc": 1, "g": 8, "index:d": `+indexStats+`, "s": "7"}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) } // Record timing duration and a uniquely Set key/value dur, _ := time.ParseDuration("123us") hldr.Stats.Timing("tt", dur, 1.0) - if stats.Expvar.String() != `{"cc": 1, "g": 8, "index:d": {"clearBit": 1, "rows": 0, "setBit": 4}, "s": "7", "tt": 123µs}` { + if stats.Expvar.String() != `{"cc": 1, "g": 8, "index:d": `+indexStats+`, "s": "7", "tt": 123µs}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) } // Expvar histogram is implemented as a gauge hldr.Stats.Histogram("hh", 3, 1.0) - if stats.Expvar.String() != `{"cc": 1, "g": 8, "hh": 3, "index:d": {"clearBit": 1, "rows": 0, "setBit": 4}, "s": "7", "tt": 123µs}` { + if stats.Expvar.String() != `{"cc": 1, "g": 8, "hh": 3, "index:d": `+indexStats+`, "s": "7", "tt": 123µs}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) } @@ -130,8 +133,8 @@ func TestStatsCount_Bitmap(t *testing.T) { called := false hldr.Holder.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, tags []string) { - if name != "query_row_total" { - t.Errorf("Expected query_row_total, Results %s", name) + if name != pilosa.MetricRow { + t.Errorf("Expected %s, Results %s", pilosa.MetricRow, name) } if tags[0] != "index:d" { @@ -165,8 +168,8 @@ func TestStatsCount_SetColumnAttrs(t *testing.T) { field.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "query_setrowattrs_total" { - t.Errorf("Expected query_setrowattrs_total, Results %s", name) + if name != pilosa.MetricSetRowAttrs { + t.Errorf("Expected %v, Results %s", pilosa.MetricSetRowAttrs, name) } called = true }, @@ -195,8 +198,8 @@ func TestStatsCount_SetProfileAttrs(t *testing.T) { idx.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "query_setcolumnattrs_total" { - t.Errorf("Expected query_setcolumnattrs_total, Results %s", name) + if name != pilosa.MetricSetColumnAttrs { + t.Errorf("Expected %v, Results %s", pilosa.MetricSetColumnAttrs, name) } called = true @@ -222,8 +225,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "create_index_total" { - t.Errorf("Expected create_index_total, Results %s", name) + if name != pilosa.MetricCreateIndex { + t.Errorf("Expected %v, Results %s", pilosa.MetricCreateIndex, name) } called = true }, @@ -239,8 +242,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, index []string) { - if name != "create_field_total" { - t.Errorf("Expected create_field_total, Results %s", name) + if name != pilosa.MetricCreateField { + t.Errorf("Expected %v, Results %s", pilosa.MetricCreateField, name) } if index[0] != "index:i" { t.Errorf("Expected index:i, Results %s", index) @@ -260,8 +263,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCountWithTags: func(name string, value int64, rate float64, index []string) { - if name != "delete_field_total" { - t.Errorf("Expected delete_field_total, Results %s", name) + if name != pilosa.MetricDeleteField { + t.Errorf("Expected %v, Results %s", pilosa.MetricDeleteField, name) } if index[0] != "index:i" { t.Errorf("Expected index:i, Results %s", index) @@ -281,8 +284,8 @@ func TestStatsCount_APICalls(t *testing.T) { called := false hldr.Stats = &MockStats{ mockCount: func(name string, value int64, rate float64) { - if name != "delete_index_total" { - t.Errorf("Expected delete_index_total, Results %s", name) + if name != pilosa.MetricDeleteIndex { + t.Errorf("Expected %v, Results %s", pilosa.MetricDeleteIndex, name) } called = true From 8b405c226c3f103d0d1062cafe5270a27a6b937b Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 9 Apr 2020 12:43:22 -0500 Subject: [PATCH 11/26] Add 'prometheus' option in other help text/comments --- ctl/server.go | 2 +- server/config.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/ctl/server.go b/ctl/server.go index ee7f9368c..9b7099a04 100644 --- a/ctl/server.go +++ b/ctl/server.go @@ -71,7 +71,7 @@ func BuildServerFlags(cmd *cobra.Command, srv *server.Command) { flags.DurationVarP((*time.Duration)(&srv.Config.AntiEntropy.Interval), "anti-entropy.interval", "", (time.Duration)(srv.Config.AntiEntropy.Interval), "Interval at which to run anti-entropy routine.") // Metric - flags.StringVarP(&srv.Config.Metric.Service, "metric.service", "", srv.Config.Metric.Service, "Where to send stats: can be expvar (in-memory served at /debug/vars), statsd or none.") + flags.StringVarP(&srv.Config.Metric.Service, "metric.service", "", srv.Config.Metric.Service, "Where to send stats: can be expvar (in-memory served at /debug/vars), prometheus, statsd or none.") flags.StringVarP(&srv.Config.Metric.Host, "metric.host", "", srv.Config.Metric.Host, "URI to send metrics when metric.service is statsd.") flags.DurationVarP((*time.Duration)(&srv.Config.Metric.PollInterval), "metric.poll-interval", "", (time.Duration)(srv.Config.Metric.PollInterval), "Polling interval metrics.") flags.BoolVarP((&srv.Config.Metric.Diagnostics), "metric.diagnostics", "", srv.Config.Metric.Diagnostics, "Enabled diagnostics reporting.") diff --git a/server/config.go b/server/config.go index 379fe6816..2d855dea6 100644 --- a/server/config.go +++ b/server/config.go @@ -131,7 +131,7 @@ type Config struct { } `toml:"anti-entropy"` Metric struct { - // Service can be statsd, expvar, or none. + // Service can be statsd, prometheus, expvar, or none. Service string `toml:"service"` // Host tells the statsd client where to write. Host string `toml:"host"` From c2c0a5c32fb1e3c9098e16386febf1d6491bf593 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 9 Apr 2020 15:15:18 -0500 Subject: [PATCH 12/26] Address review feedback --- executor.go | 51 ++++++++++++++++++++++++++-------------- http/handler.go | 4 ++-- prometheus/prometheus.go | 2 +- 3 files changed, 37 insertions(+), 20 deletions(-) diff --git a/executor.go b/executor.go index daf3f1320..cce98d5d3 100644 --- a/executor.go +++ b/executor.go @@ -464,6 +464,11 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s } indexTag := "index:" + index metricName := "query_" + strings.ToLower(c.Name) + "_total" + statFn := func() { + if !opt.Remote { + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + } + } // Fixes #2009 // See: https://github.com/pilosa/pilosa/issues/2009 @@ -488,63 +493,71 @@ func (e *executor) executeCall(ctx context.Context, index string, c *pql.Call, s // Special handling for mutation and top-n calls. if op, ok := e.additionalCountOps[c.Name]; ok { - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeGenericCount(ctx, index, c, op, shards, opt) } if op, ok := e.additionalFieldOps[c.Name]; ok { - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeGenericField(ctx, index, c, op, shards, opt) } switch c.Name { case "Sum": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeSum(ctx, index, c, shards, opt) case "Min": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeMin(ctx, index, c, shards, opt) case "Max": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeMax(ctx, index, c, shards, opt) case "MinRow": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeMinRow(ctx, index, c, shards, opt) case "MaxRow": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeMaxRow(ctx, index, c, shards, opt) case "Clear": + statFn() return e.executeClearBit(ctx, index, c, opt) case "ClearRow": + statFn() return e.executeClearRow(ctx, index, c, shards, opt) case "Store": + statFn() return e.executeSetRow(ctx, index, c, shards, opt) case "Count": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeCount(ctx, index, c, shards, opt) case "Set": + statFn() return e.executeSet(ctx, index, c, opt) case "SetRowAttrs": + statFn() return nil, e.executeSetRowAttrs(ctx, index, c, opt) case "SetColumnAttrs": + statFn() return nil, e.executeSetColumnAttrs(ctx, index, c, opt) case "TopN": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeTopN(ctx, index, c, shards, opt) case "Rows": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeRows(ctx, index, c, shards, opt) case "GroupBy": - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeGroupBy(ctx, index, c, shards, opt) case "Options": + statFn() return e.executeOptionsCall(ctx, index, c, shards, opt) case "IncludesColumn": return e.executeIncludesColumnCall(ctx, index, c, shards, opt) case "All": + statFn() return e.executeAllCall(ctx, index, c, shards, opt) case "Precomputed": return e.executePrecomputedCall(ctx, index, c, shards, opt) default: - e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + statFn() return e.executeBitmapCall(ctx, index, c, shards, opt) } } @@ -1024,6 +1037,15 @@ func (e *executor) executeBitmapCall(ctx context.Context, index string, c *pql.C span, ctx := tracing.StartSpanFromContext(ctx, "Executor.executeBitmapCall") defer span.Finish() + indexTag := "index:" + index + metricName := "query_" + strings.ToLower(c.Name) + "_total" + if c.Name == "Row" && c.HasConditionArg() { + metricName = "query_row_bsi_total" + } + if !opt.Remote { + e.Holder.Stats.CountWithCustomTags(metricName, 1, 1.0, []string{indexTag}) + } + // Execute calls in bulk on each remote node and merge. mapFn := func(shard uint64) (interface{}, error) { return e.executeBitmapCallShard(ctx, index, c, shard) @@ -2283,7 +2305,6 @@ func (e *executor) executeRowBSIGroupShard(ctx context.Context, index string, c return NewRow(), nil } - f.Stats.Count(MetricRowBSI, 1, 1.0) return frag.notNull() } else if cond.Op == pql.BETWEEN || cond.Op == pql.BTWN_LT_LT || @@ -2325,7 +2346,6 @@ func (e *executor) executeRowBSIGroupShard(ctx context.Context, index string, c return frag.notNull() } - f.Stats.Count(MetricRowBSI, 1, 1.0) return frag.rangeBetween(bsig.BitDepth, baseValueMin, baseValueMax) } else { @@ -2362,7 +2382,6 @@ func (e *executor) executeRowBSIGroupShard(ctx context.Context, index string, c return frag.notNull() } - f.Stats.Count(MetricRowBSI, 1, 1.0) return frag.rangeOp(cond.Op, bsig.BitDepth, baseValue) } } @@ -3105,7 +3124,6 @@ func (e *executor) executeSetRowAttrs(ctx context.Context, index string, c *pql. if err := field.RowAttrStore().SetAttrs(rowID, attrs); err != nil { return err } - field.Stats.Count(MetricSetRowAttrs, 1, 1.0) // Do not forward call if this is already being forwarded. if opt.Remote { @@ -3253,7 +3271,6 @@ func (e *executor) executeSetColumnAttrs(ctx context.Context, index string, c *p if err := idx.ColumnAttrStore().SetAttrs(col, attrs); err != nil { return err } - idx.Stats.Count(MetricSetColumnAttrs, 1, 1.0) // Do not forward call if this is already being forwarded. if opt.Remote { return nil diff --git a/http/handler.go b/http/handler.go index 6cb5a08c5..1ffc4df4f 100644 --- a/http/handler.go +++ b/http/handler.go @@ -277,12 +277,12 @@ func (h *Handler) collectStats(next http.Handler) http.Handler { } h.logger.Printf("%s %s %v %s", r.Method, r.URL.String(), dur, queryString) - statsTags = append(statsTags, "slow_query") + statsTags = append(statsTags, "speed:true") } pathParts := strings.Split(r.URL.Path, "/") if externalPrefixFlag[pathParts[1]] { - statsTags = append(statsTags, "external") + statsTags = append(statsTags, "where:external") } statsTags = append(statsTags, "useragent:"+r.UserAgent()) diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index 4208e29a5..b093d3292 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -252,7 +252,7 @@ func (c *prometheusClient) Set(name string, value string, rate float64) { // Timing tracks timing information for a metric. func (c *prometheusClient) Timing(name string, value time.Duration, rate float64) { - durationS := value / time.Second + durationS := float64(value) / float64(time.Second) c.Histogram(name, float64(durationS), rate) } From 389acfc8eda4f9b402f9c0fefb9e8651f94a55a1 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 9 Apr 2020 17:00:20 -0500 Subject: [PATCH 13/26] Fix minor issues with metric labels and tests --- executor.go | 6 +++++- http/handler.go | 6 +++++- prometheus/prometheus.go | 2 +- stats/stats_test.go | 19 +++++++++++++------ 4 files changed, 24 insertions(+), 9 deletions(-) diff --git a/executor.go b/executor.go index cce98d5d3..f2cd94dff 100644 --- a/executor.go +++ b/executor.go @@ -3217,7 +3217,11 @@ func (e *executor) executeBulkSetRowAttrs(ctx context.Context, index string, cal if err := field.RowAttrStore().SetBulkAttrs(fieldMap); err != nil { return nil, err } - field.Stats.Count(MetricSetRowAttrs, 1, 1.0) + } + + if !opt.Remote { + tags := []string{"index:" + index, "bulk:true"} + e.Holder.Stats.CountWithCustomTags(MetricSetRowAttrs, int64(len(m)), 1.0, tags) } // Do not forward call if this is already being forwarded. diff --git a/http/handler.go b/http/handler.go index 1ffc4df4f..4b77422d9 100644 --- a/http/handler.go +++ b/http/handler.go @@ -277,12 +277,16 @@ func (h *Handler) collectStats(next http.Handler) http.Handler { } h.logger.Printf("%s %s %v %s", r.Method, r.URL.String(), dur, queryString) - statsTags = append(statsTags, "speed:true") + statsTags = append(statsTags, "slow:true") + } else { + statsTags = append(statsTags, "slow:false") } pathParts := strings.Split(r.URL.Path, "/") if externalPrefixFlag[pathParts[1]] { statsTags = append(statsTags, "where:external") + } else { + statsTags = append(statsTags, "where:internal") } statsTags = append(statsTags, "useragent:"+r.UserAgent()) diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index b093d3292..4567d0f11 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -302,7 +302,7 @@ func tagsToLabels(tags []string, logger logger.Logger) (labels prometheus.Labels tagParts := strings.SplitAfterN(tag, ":", 2) if len(tagParts) != 2 { // only process tags in "key:value" form - logger.Debugf("Invalid Prometheus label: %v\n", tag) + logger.Printf("Error: invalid Prometheus label: %v\n", tag) continue } labels[tagParts[0][0:len(tagParts[0])-1]] = tagParts[1] diff --git a/stats/stats_test.go b/stats/stats_test.go index 8ac3606c2..c116e8168 100644 --- a/stats/stats_test.go +++ b/stats/stats_test.go @@ -152,7 +152,7 @@ func TestStatsCount_Bitmap(t *testing.T) { } } -func TestStatsCount_SetColumnAttrs(t *testing.T) { +func TestStatsCount_SetRowAttrsBulk(t *testing.T) { c := test.MustRunCluster(t, 1) defer c.Close() hldr := test.Holder{Holder: c[0].Server.Holder()} @@ -166,11 +166,15 @@ func TestStatsCount_SetColumnAttrs(t *testing.T) { t.Fatal("field not found") } - field.Stats = &MockStats{ - mockCount: func(name string, value int64, rate float64) { + hldr.Holder.Stats = &MockStats{ + mockCountWithTags: func(name string, value int64, rate float64, tags []string) { if name != pilosa.MetricSetRowAttrs { t.Errorf("Expected %v, Results %s", pilosa.MetricSetRowAttrs, name) } + + if tags[0] != "index:d" { + t.Errorf("Expected db, Results %s", tags[0]) + } called = true }, } @@ -182,7 +186,7 @@ func TestStatsCount_SetColumnAttrs(t *testing.T) { } } -func TestStatsCount_SetProfileAttrs(t *testing.T) { +func TestStatsCount_SetColumnAttrs(t *testing.T) { c := test.MustRunCluster(t, 1) defer c.Close() hldr := test.Holder{Holder: c[0].Server.Holder()} @@ -196,12 +200,15 @@ func TestStatsCount_SetProfileAttrs(t *testing.T) { t.Fatal("idex not found") } - idx.Stats = &MockStats{ - mockCount: func(name string, value int64, rate float64) { + hldr.Holder.Stats = &MockStats{ + mockCountWithTags: func(name string, value int64, rate float64, tags []string) { if name != pilosa.MetricSetColumnAttrs { t.Errorf("Expected %v, Results %s", pilosa.MetricSetColumnAttrs, name) } + if tags[0] != "index:d" { + t.Errorf("Expected db, Results %s", tags[0]) + } called = true }, } From f883d61c28b9d1c4193b7c32aa635af8fb4524ec Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 9 Apr 2020 17:20:17 -0500 Subject: [PATCH 14/26] Consolidate BlockRepair metrics with tags --- fragment.go | 4 ++-- metrics.go | 1 - 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/fragment.go b/fragment.go index 588ea77ae..e9a7eec7d 100644 --- a/fragment.go +++ b/fragment.go @@ -3044,13 +3044,13 @@ func (s *fragmentSyncer) syncFragment() error { if err := s.syncBlockFromPrimary(blockID); err != nil { return fmt.Errorf("sync block from primary: id=%d, err=%s", blockID, err) } - s.Fragment.stats.Count(MetricBlockRepairPrimary, 1, 1.0) + s.Fragment.stats.CountWithCustomTags(MetricBlockRepair, 1, 1.0, []string{"primary:true"}) default: // Synchronize block. if err := s.syncBlock(blockID); err != nil { return fmt.Errorf("sync block: id=%d, err=%s", blockID, err) } - s.Fragment.stats.Count(MetricBlockRepair, 1, 1.0) + s.Fragment.stats.CountWithCustomTags(MetricBlockRepair, 1, 1.0, []string{"primary:false"}) } } diff --git a/metrics.go b/metrics.go index fc451772f..93cb6b649 100644 --- a/metrics.go +++ b/metrics.go @@ -38,7 +38,6 @@ const ( MetricClearingN = "clearing_total" MetricClearedN = "cleared_total" MetricSnapshotDuration = "snapshot_duration_seconds" - MetricBlockRepairPrimary = "block_repair_primary_total" MetricBlockRepair = "block_repair_total" MetricSyncFieldDuration = "sync_field_duration_seconds" MetricSyncIndexDuration = "sync_index_duration_seconds" From 2423ecf8d5a01864f6f0e1e0c68947f7babaf6d8 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Thu, 9 Apr 2020 17:21:17 -0500 Subject: [PATCH 15/26] Update some metric names to follow conventions better --- fragment.go | 2 +- holder.go | 4 +-- http/handler.go | 2 +- metrics.go | 84 ++++++++++++++++++++++----------------------- server.go | 2 +- stats/stats_test.go | 8 ++--- 6 files changed, 51 insertions(+), 51 deletions(-) diff --git a/fragment.go b/fragment.go index e9a7eec7d..b4dc828d1 100644 --- a/fragment.go +++ b/fragment.go @@ -2249,7 +2249,7 @@ func (f *fragment) Snapshot() error { func track(start time.Time, message string, stats stats.StatsClient, logger logger.Logger) { elapsed := time.Since(start) logger.Debugf("%s took %s", message, elapsed) - stats.Histogram(MetricSnapshotDuration, elapsed.Seconds(), 1.0) + stats.Histogram(MetricSnapshotDurationSeconds, elapsed.Seconds(), 1.0) } // snapshot does the actual snapshot operation. it does not check or care diff --git a/holder.go b/holder.go index 8ae7a32dc..247bce041 100644 --- a/holder.go +++ b/holder.go @@ -801,10 +801,10 @@ func (s *holderSyncer) SyncHolder() error { } } } - s.Stats.Histogram(MetricSyncFieldDuration, float64(time.Since(tf)), 1.0) + s.Stats.Histogram(MetricSyncFieldDurationSeconds, float64(time.Since(tf)), 1.0) tf = time.Now() // reset tf } - s.Stats.Histogram(MetricSyncIndexDuration, float64(time.Since(ti)), 1.0) + s.Stats.Histogram(MetricSyncIndexDurationSeconds, float64(time.Since(ti)), 1.0) ti = time.Now() // reset ti } diff --git a/http/handler.go b/http/handler.go index 4b77422d9..51ce25991 100644 --- a/http/handler.go +++ b/http/handler.go @@ -300,7 +300,7 @@ func (h *Handler) collectStats(next http.Handler) http.Handler { stats := h.api.StatsWithTags(statsTags) if stats != nil { - stats.Timing(pilosa.MetricHttpRequest, dur, 0.1) + stats.Timing(pilosa.MetricHTTPRequest, dur, 0.1) } }) } diff --git a/metrics.go b/metrics.go index 93cb6b649..a8afa8e41 100644 --- a/metrics.go +++ b/metrics.go @@ -15,46 +15,46 @@ package pilosa const ( - MetricCreateIndex = "create_index_total" - MetricDeleteIndex = "delete_index_total" - MetricCreateField = "create_field_total" - MetricDeleteField = "delete_field_total" - MetricDeleteAvailableShard = "delete_available_shard_total" - MetricRecalculateCache = "recalculate_cache_total" - MetricInvalidateCache = "invalidate_cache_total" - MetricRankCacheLength = "rank_cache_length" - MetricCacheThresholdReached = "cache_threshold_reached_total" - MetricRow = "query_row_total" - MetricRowBSI = "query_row_bsi_total" - MetricSetRowAttrs = "query_setrowattrs_total" - MetricSetColumnAttrs = "query_setcolumnattrs_total" - MetricMaximumRow = "maximum_row" - MetricSetBit = "set_bit_total" - MetricClearBit = "clear_bit_total" - MetricSetRow = "set_row_total" - MetricClearRow = "clear_row_total" - MetricImportingN = "importing_total" - MetricImportedN = "imported_total" - MetricClearingN = "clearing_total" - MetricClearedN = "cleared_total" - MetricSnapshotDuration = "snapshot_duration_seconds" - MetricBlockRepair = "block_repair_total" - MetricSyncFieldDuration = "sync_field_duration_seconds" - MetricSyncIndexDuration = "sync_index_duration_seconds" - MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" - MetricColumnAttrDiff = "ColumnAttrDiff" - MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" - MetricRowAttrDiff = "RowAttrDiff" - MetricHttpRequest = "http_request_total" - MetricMaxShard = "maximum_shard" - MetricAntiEntropy = "antientropy_total" - MetricAntiEntropyDuration = "antientropy_duration_seconds" - MetricGarbageCollection = "garbage_collection_total" - MetricGoroutines = "goroutines" - MetricOpenFiles = "open_files" - MetricHeapAlloc = "heap_alloc" - MetricHeapInuse = "heap_inuse" - MetricStackInuse = "stack_inuse" - MetricMallocs = "mallocs" - MetricFrees = "frees" + MetricCreateIndex = "create_index_total" + MetricDeleteIndex = "delete_index_total" + MetricCreateField = "create_field_total" + MetricDeleteField = "delete_field_total" + MetricDeleteAvailableShard = "delete_available_shard_total" + MetricRecalculateCache = "recalculate_cache_total" + MetricInvalidateCache = "invalidate_cache_total" + MetricRankCacheLength = "rank_cache_length" + MetricCacheThresholdReached = "cache_threshold_reached_total" + MetricRow = "query_row_total" + MetricRowBSI = "query_row_bsi_total" + MetricSetRowAttrs = "query_setrowattrs_total" + MetricSetColumnAttrs = "query_setcolumnattrs_total" + MetricMaximumRow = "maximum_row" + MetricSetBit = "set_bit_total" + MetricClearBit = "clear_bit_total" + MetricSetRow = "set_row_total" + MetricClearRow = "clear_row_total" + MetricImportingN = "importing_total" + MetricImportedN = "imported_total" + MetricClearingN = "clearing_total" + MetricClearedN = "cleared_total" + MetricSnapshotDurationSeconds = "snapshot_duration_seconds" + MetricBlockRepair = "block_repair_total" + MetricSyncFieldDurationSeconds = "sync_field_duration_seconds" + MetricSyncIndexDurationSeconds = "sync_index_duration_seconds" + MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" + MetricColumnAttrDiff = "ColumnAttrDiff" + MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" + MetricRowAttrDiff = "RowAttrDiff" + MetricHTTPRequest = "http_request_total" + MetricMaxShard = "maximum_shard" + MetricAntiEntropy = "antientropy_total" + MetricAntiEntropyDurationSeconds = "antientropy_duration_seconds" + MetricGarbageCollection = "garbage_collection_total" + MetricGoroutines = "goroutines" + MetricOpenFiles = "open_files" + MetricHeapAlloc = "heap_alloc" + MetricHeapInuse = "heap_inuse" + MetricStackInuse = "stack_inuse" + MetricMallocs = "mallocs" + MetricFrees = "frees" ) diff --git a/server.go b/server.go index 9c11d216f..957f45100 100644 --- a/server.go +++ b/server.go @@ -675,7 +675,7 @@ func (s *Server) monitorAntiEntropy() { // Record successful sync in log. s.logger.Printf("holder sync complete") dif := time.Since(t) - s.holder.Stats.Histogram(MetricAntiEntropyDuration, float64(dif), 1.0) + s.holder.Stats.Histogram(MetricAntiEntropyDurationSeconds, float64(dif), 1.0) // Drain tick channel since we just finished anti-entropy. If the AE // process took a long time, we don't want them to pile up on each diff --git a/stats/stats_test.go b/stats/stats_test.go index c116e8168..fe8eb65ac 100644 --- a/stats/stats_test.go +++ b/stats/stats_test.go @@ -109,7 +109,7 @@ func TestStatsCount_TopN(t *testing.T) { } if tags[0] != "index:d" { - t.Errorf("Expected db, Results %s", tags[0]) + t.Errorf("Expected index, Results %s", tags[0]) } called = true @@ -138,7 +138,7 @@ func TestStatsCount_Bitmap(t *testing.T) { } if tags[0] != "index:d" { - t.Errorf("Expected db, Results %s", tags[0]) + t.Errorf("Expected index, Results %s", tags[0]) } called = true @@ -173,7 +173,7 @@ func TestStatsCount_SetRowAttrsBulk(t *testing.T) { } if tags[0] != "index:d" { - t.Errorf("Expected db, Results %s", tags[0]) + t.Errorf("Expected index, Results %s", tags[0]) } called = true }, @@ -207,7 +207,7 @@ func TestStatsCount_SetColumnAttrs(t *testing.T) { } if tags[0] != "index:d" { - t.Errorf("Expected db, Results %s", tags[0]) + t.Errorf("Expected index, Results %s", tags[0]) } called = true }, From df2503dfa62fd3de5f747e41f7cfea120812add3 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 09:00:11 -0500 Subject: [PATCH 16/26] Switch to Timing helper function --- fragment.go | 2 +- holder.go | 4 ++-- server.go | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/fragment.go b/fragment.go index b4dc828d1..149749230 100644 --- a/fragment.go +++ b/fragment.go @@ -2249,7 +2249,7 @@ func (f *fragment) Snapshot() error { func track(start time.Time, message string, stats stats.StatsClient, logger logger.Logger) { elapsed := time.Since(start) logger.Debugf("%s took %s", message, elapsed) - stats.Histogram(MetricSnapshotDurationSeconds, elapsed.Seconds(), 1.0) + stats.Timing(MetricSnapshotDurationSeconds, elapsed, 1.0) } // snapshot does the actual snapshot operation. it does not check or care diff --git a/holder.go b/holder.go index 247bce041..51a89826b 100644 --- a/holder.go +++ b/holder.go @@ -801,10 +801,10 @@ func (s *holderSyncer) SyncHolder() error { } } } - s.Stats.Histogram(MetricSyncFieldDurationSeconds, float64(time.Since(tf)), 1.0) + s.Stats.Timing(MetricSyncFieldDurationSeconds, time.Since(tf), 1.0) tf = time.Now() // reset tf } - s.Stats.Histogram(MetricSyncIndexDurationSeconds, float64(time.Since(ti)), 1.0) + s.Stats.Timing(MetricSyncIndexDurationSeconds, time.Since(ti), 1.0) ti = time.Now() // reset ti } diff --git a/server.go b/server.go index 957f45100..ab90bbc9a 100644 --- a/server.go +++ b/server.go @@ -675,7 +675,7 @@ func (s *Server) monitorAntiEntropy() { // Record successful sync in log. s.logger.Printf("holder sync complete") dif := time.Since(t) - s.holder.Stats.Histogram(MetricAntiEntropyDurationSeconds, float64(dif), 1.0) + s.holder.Stats.Timing(MetricAntiEntropyDurationSeconds, dif, 1.0) // Drain tick channel since we just finished anti-entropy. If the AE // process took a long time, we don't want them to pile up on each From b1838159f240083e3048d020ce5ed4f58bb3fd8a Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 11:31:09 -0500 Subject: [PATCH 17/26] Minor fixes --- fragment.go | 3 --- metrics.go | 4 +--- prometheus/prometheus.go | 3 +-- 3 files changed, 2 insertions(+), 8 deletions(-) diff --git a/fragment.go b/fragment.go index 149749230..d24c856d2 100644 --- a/fragment.go +++ b/fragment.go @@ -691,7 +691,6 @@ func (f *fragment) unprotectedSetRow(row *Row, rowID uint64) (changed bool, err // Snapshot storage. f.snapshotQueue.Enqueue(f) - f.stats.Count(MetricSetRow, 1, 1.0) return changed, nil } @@ -733,8 +732,6 @@ func (f *fragment) unprotectedClearRow(rowID uint64) (changed bool, err error) { // Snapshot storage. f.snapshotQueue.Enqueue(f) - f.stats.Count(MetricClearRow, 1, 1.0) - return changed, nil } diff --git a/metrics.go b/metrics.go index a8afa8e41..0e3ce1208 100644 --- a/metrics.go +++ b/metrics.go @@ -28,11 +28,9 @@ const ( MetricRowBSI = "query_row_bsi_total" MetricSetRowAttrs = "query_setrowattrs_total" MetricSetColumnAttrs = "query_setcolumnattrs_total" - MetricMaximumRow = "maximum_row" + MetricMaximumRow = "shard_maximum_row" MetricSetBit = "set_bit_total" MetricClearBit = "clear_bit_total" - MetricSetRow = "set_row_total" - MetricClearRow = "clear_row_total" MetricImportingN = "importing_total" MetricImportedN = "imported_total" MetricClearingN = "clearing_total" diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index 4567d0f11..551996fb9 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -252,8 +252,7 @@ func (c *prometheusClient) Set(name string, value string, rate float64) { // Timing tracks timing information for a metric. func (c *prometheusClient) Timing(name string, value time.Duration, rate float64) { - durationS := float64(value) / float64(time.Second) - c.Histogram(name, float64(durationS), rate) + c.Histogram(name, value.Seconds(), rate) } // SetLogger sets the logger for client. From b37a0addb3d80ff3f6005cfe1210f0365c0f5203 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 11:31:48 -0500 Subject: [PATCH 18/26] Add tags to MaxRow metric --- fragment.go | 9 +++++++-- prometheus/prometheus.go | 5 +++++ stats/stats.go | 31 +++++++++++++++++++++++++------ 3 files changed, 37 insertions(+), 8 deletions(-) diff --git a/fragment.go b/fragment.go index d24c856d2..3f46c5444 100644 --- a/fragment.go +++ b/fragment.go @@ -30,6 +30,7 @@ import ( "os" "runtime/debug" "sort" + "strconv" "strings" "sync" "syscall" @@ -208,7 +209,9 @@ func (f *fragment) Open() error { // Read last bit to determine max row. f.maxRowID = f.storage.Max() / ShardWidth - f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) + fieldTag := "field:" + f.field + shardTag := "shard:" + strconv.FormatInt(int64(f.shard), 10) + f.stats.GaugeWithCustomTags(MetricMaximumRow, float64(f.maxRowID), 1.0, []string{fieldTag, shardTag}) return nil }(); err != nil { f.close() @@ -581,7 +584,9 @@ func (f *fragment) unprotectedSetBit(rowID, columnID uint64) (changed bool, err // Update row count if they have increased. if rowID > f.maxRowID { f.maxRowID = rowID - f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) + fieldTag := "field:" + f.field + shardTag := "shard:" + strconv.FormatInt(int64(f.shard), 10) + f.stats.GaugeWithCustomTags(MetricMaximumRow, float64(f.maxRowID), 1.0, []string{fieldTag, shardTag}) } return changed, nil diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index 551996fb9..8dfd966ec 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -202,6 +202,11 @@ func (c *prometheusClient) Gauge(name string, value float64, rate float64) { gauge.Set(float64(value)) } +// GaugeWithCustomTags sets the value of a metric with custom tags. +func (c *prometheusClient) GaugeWithCustomTags(name string, value float64, rate float64, t []string) { + c.WithTags(append(c.tags, t...)...).Gauge(name, value, rate) +} + // Histogram tracks statistical distribution of a metric. func (c *prometheusClient) Histogram(name string, value float64, rate float64) { mu.Lock() diff --git a/stats/stats.go b/stats/stats.go index c360baab0..226f6611f 100644 --- a/stats/stats.go +++ b/stats/stats.go @@ -44,6 +44,9 @@ type StatsClient interface { // Sets the value of a metric. Gauge(name string, value float64, rate float64) + // Sets the value of a metric with custom tags + GaugeWithCustomTags(name string, value float64, rate float64, tags []string) + // Tracks statistical distribution of a metric. Histogram(name string, value float64, rate float64) @@ -73,12 +76,14 @@ func (c *nopStatsClient) WithTags(tags ...string) StatsClient func (c *nopStatsClient) Count(name string, value int64, rate float64) {} func (c *nopStatsClient) CountWithCustomTags(name string, value int64, rate float64, tags []string) {} func (c *nopStatsClient) Gauge(name string, value float64, rate float64) {} -func (c *nopStatsClient) Histogram(name string, value float64, rate float64) {} -func (c *nopStatsClient) Set(name string, value string, rate float64) {} -func (c *nopStatsClient) Timing(name string, value time.Duration, rate float64) {} -func (c *nopStatsClient) SetLogger(logger logger.Logger) {} -func (c *nopStatsClient) Open() {} -func (c *nopStatsClient) Close() error { return nil } +func (c *nopStatsClient) GaugeWithCustomTags(name string, value float64, rate float64, tags []string) { +} +func (c *nopStatsClient) Histogram(name string, value float64, rate float64) {} +func (c *nopStatsClient) Set(name string, value string, rate float64) {} +func (c *nopStatsClient) Timing(name string, value time.Duration, rate float64) {} +func (c *nopStatsClient) SetLogger(logger logger.Logger) {} +func (c *nopStatsClient) Open() {} +func (c *nopStatsClient) Close() error { return nil } // expvarStatsClient writes stats out to expvars. type expvarStatsClient struct { @@ -132,6 +137,13 @@ func (c *expvarStatsClient) Gauge(name string, value float64, rate float64) { c.m.Set(name, &f) } +// GaugeWithCustomTags Sets the value of a metric with custom tags +func (c *expvarStatsClient) GaugeWithCustomTags(name string, value float64, rate float64, tags []string) { + var f expvar.Float + f.Set(value) + c.m.Set(name, &f) +} + // Histogram tracks statistical distribution of a metric. // This works the same as gauge for this client. func (c *expvarStatsClient) Histogram(name string, value float64, rate float64) { @@ -204,6 +216,13 @@ func (a MultiStatsClient) Gauge(name string, value float64, rate float64) { } } +// GaugeWithCustomTags Sets the value of a metric with custom tags +func (a MultiStatsClient) GaugeWithCustomTags(name string, value float64, rate float64, tags []string) { + for _, c := range a { + c.GaugeWithCustomTags(name, value, rate, tags) + } +} + // Histogram tracks statistical distribution of a metric on all clients. func (a MultiStatsClient) Histogram(name string, value float64, rate float64) { for _, c := range a { From a7bfacbee24b11e2e46f2b4cce16f4152885a342 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 11:41:11 -0500 Subject: [PATCH 19/26] Revert "Add tags to MaxRow metric" This reverts commit 6013e7211b3aef93d0880401c8ef74b34a620328. --- fragment.go | 9 ++------- prometheus/prometheus.go | 5 ----- stats/stats.go | 31 ++++++------------------------- 3 files changed, 8 insertions(+), 37 deletions(-) diff --git a/fragment.go b/fragment.go index 3f46c5444..d24c856d2 100644 --- a/fragment.go +++ b/fragment.go @@ -30,7 +30,6 @@ import ( "os" "runtime/debug" "sort" - "strconv" "strings" "sync" "syscall" @@ -209,9 +208,7 @@ func (f *fragment) Open() error { // Read last bit to determine max row. f.maxRowID = f.storage.Max() / ShardWidth - fieldTag := "field:" + f.field - shardTag := "shard:" + strconv.FormatInt(int64(f.shard), 10) - f.stats.GaugeWithCustomTags(MetricMaximumRow, float64(f.maxRowID), 1.0, []string{fieldTag, shardTag}) + f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) return nil }(); err != nil { f.close() @@ -584,9 +581,7 @@ func (f *fragment) unprotectedSetBit(rowID, columnID uint64) (changed bool, err // Update row count if they have increased. if rowID > f.maxRowID { f.maxRowID = rowID - fieldTag := "field:" + f.field - shardTag := "shard:" + strconv.FormatInt(int64(f.shard), 10) - f.stats.GaugeWithCustomTags(MetricMaximumRow, float64(f.maxRowID), 1.0, []string{fieldTag, shardTag}) + f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) } return changed, nil diff --git a/prometheus/prometheus.go b/prometheus/prometheus.go index 8dfd966ec..551996fb9 100644 --- a/prometheus/prometheus.go +++ b/prometheus/prometheus.go @@ -202,11 +202,6 @@ func (c *prometheusClient) Gauge(name string, value float64, rate float64) { gauge.Set(float64(value)) } -// GaugeWithCustomTags sets the value of a metric with custom tags. -func (c *prometheusClient) GaugeWithCustomTags(name string, value float64, rate float64, t []string) { - c.WithTags(append(c.tags, t...)...).Gauge(name, value, rate) -} - // Histogram tracks statistical distribution of a metric. func (c *prometheusClient) Histogram(name string, value float64, rate float64) { mu.Lock() diff --git a/stats/stats.go b/stats/stats.go index 226f6611f..c360baab0 100644 --- a/stats/stats.go +++ b/stats/stats.go @@ -44,9 +44,6 @@ type StatsClient interface { // Sets the value of a metric. Gauge(name string, value float64, rate float64) - // Sets the value of a metric with custom tags - GaugeWithCustomTags(name string, value float64, rate float64, tags []string) - // Tracks statistical distribution of a metric. Histogram(name string, value float64, rate float64) @@ -76,14 +73,12 @@ func (c *nopStatsClient) WithTags(tags ...string) StatsClient func (c *nopStatsClient) Count(name string, value int64, rate float64) {} func (c *nopStatsClient) CountWithCustomTags(name string, value int64, rate float64, tags []string) {} func (c *nopStatsClient) Gauge(name string, value float64, rate float64) {} -func (c *nopStatsClient) GaugeWithCustomTags(name string, value float64, rate float64, tags []string) { -} -func (c *nopStatsClient) Histogram(name string, value float64, rate float64) {} -func (c *nopStatsClient) Set(name string, value string, rate float64) {} -func (c *nopStatsClient) Timing(name string, value time.Duration, rate float64) {} -func (c *nopStatsClient) SetLogger(logger logger.Logger) {} -func (c *nopStatsClient) Open() {} -func (c *nopStatsClient) Close() error { return nil } +func (c *nopStatsClient) Histogram(name string, value float64, rate float64) {} +func (c *nopStatsClient) Set(name string, value string, rate float64) {} +func (c *nopStatsClient) Timing(name string, value time.Duration, rate float64) {} +func (c *nopStatsClient) SetLogger(logger logger.Logger) {} +func (c *nopStatsClient) Open() {} +func (c *nopStatsClient) Close() error { return nil } // expvarStatsClient writes stats out to expvars. type expvarStatsClient struct { @@ -137,13 +132,6 @@ func (c *expvarStatsClient) Gauge(name string, value float64, rate float64) { c.m.Set(name, &f) } -// GaugeWithCustomTags Sets the value of a metric with custom tags -func (c *expvarStatsClient) GaugeWithCustomTags(name string, value float64, rate float64, tags []string) { - var f expvar.Float - f.Set(value) - c.m.Set(name, &f) -} - // Histogram tracks statistical distribution of a metric. // This works the same as gauge for this client. func (c *expvarStatsClient) Histogram(name string, value float64, rate float64) { @@ -216,13 +204,6 @@ func (a MultiStatsClient) Gauge(name string, value float64, rate float64) { } } -// GaugeWithCustomTags Sets the value of a metric with custom tags -func (a MultiStatsClient) GaugeWithCustomTags(name string, value float64, rate float64, tags []string) { - for _, c := range a { - c.GaugeWithCustomTags(name, value, rate, tags) - } -} - // Histogram tracks statistical distribution of a metric on all clients. func (a MultiStatsClient) Histogram(name string, value float64, rate float64) { for _, c := range a { From d79f04b7b3012fbb1c1885a38a717af6fb9e10da Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 11:42:21 -0500 Subject: [PATCH 20/26] Remove MetricMaximumRow --- fragment.go | 2 -- metrics.go | 1 - 2 files changed, 3 deletions(-) diff --git a/fragment.go b/fragment.go index d24c856d2..285092732 100644 --- a/fragment.go +++ b/fragment.go @@ -208,7 +208,6 @@ func (f *fragment) Open() error { // Read last bit to determine max row. f.maxRowID = f.storage.Max() / ShardWidth - f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) return nil }(); err != nil { f.close() @@ -581,7 +580,6 @@ func (f *fragment) unprotectedSetBit(rowID, columnID uint64) (changed bool, err // Update row count if they have increased. if rowID > f.maxRowID { f.maxRowID = rowID - f.stats.Gauge(MetricMaximumRow, float64(f.maxRowID), 1.0) } return changed, nil diff --git a/metrics.go b/metrics.go index 0e3ce1208..f8baea30a 100644 --- a/metrics.go +++ b/metrics.go @@ -28,7 +28,6 @@ const ( MetricRowBSI = "query_row_bsi_total" MetricSetRowAttrs = "query_setrowattrs_total" MetricSetColumnAttrs = "query_setcolumnattrs_total" - MetricMaximumRow = "shard_maximum_row" MetricSetBit = "set_bit_total" MetricClearBit = "clear_bit_total" MetricImportingN = "importing_total" From 5df680fb9f4d7828f4fe4ca901505a7b14418131 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 12:00:37 -0500 Subject: [PATCH 21/26] Remove old metric from tests --- stats/stats_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/stats/stats_test.go b/stats/stats_test.go index fe8eb65ac..8e9cb8de2 100644 --- a/stats/stats_test.go +++ b/stats/stats_test.go @@ -46,7 +46,7 @@ func TestMultiStatClient_Expvar(t *testing.T) { hldr.SetBit("d", "f", 0, pilosa.ShardWidth+2) hldr.ClearBit("d", "f", 0, 1) - indexStats := fmt.Sprintf(`{"%s": %d, "%s": %d, "%s": %d}`, pilosa.MetricClearBit, 1, pilosa.MetricMaximumRow, 0, pilosa.MetricSetBit, 4) + indexStats := fmt.Sprintf(`{"%s": %d, "%s": %d}`, pilosa.MetricClearBit, 1, pilosa.MetricSetBit, 4) if stats.Expvar.String() != `{"index:d": `+indexStats+`}` { t.Fatalf("unexpected expvar : %s", stats.Expvar.String()) From eaf21eb19bfe8f73b870aa4c1e97f67bd373e4e9 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 12:27:20 -0500 Subject: [PATCH 22/26] Add metrics for GRPC request timing --- metrics.go | 82 +++++++++++++++++++++++++----------------------- server/grpc.go | 28 ++++++++++++++++- server/server.go | 1 + 3 files changed, 71 insertions(+), 40 deletions(-) diff --git a/metrics.go b/metrics.go index f8baea30a..7324fdedb 100644 --- a/metrics.go +++ b/metrics.go @@ -15,43 +15,47 @@ package pilosa const ( - MetricCreateIndex = "create_index_total" - MetricDeleteIndex = "delete_index_total" - MetricCreateField = "create_field_total" - MetricDeleteField = "delete_field_total" - MetricDeleteAvailableShard = "delete_available_shard_total" - MetricRecalculateCache = "recalculate_cache_total" - MetricInvalidateCache = "invalidate_cache_total" - MetricRankCacheLength = "rank_cache_length" - MetricCacheThresholdReached = "cache_threshold_reached_total" - MetricRow = "query_row_total" - MetricRowBSI = "query_row_bsi_total" - MetricSetRowAttrs = "query_setrowattrs_total" - MetricSetColumnAttrs = "query_setcolumnattrs_total" - MetricSetBit = "set_bit_total" - MetricClearBit = "clear_bit_total" - MetricImportingN = "importing_total" - MetricImportedN = "imported_total" - MetricClearingN = "clearing_total" - MetricClearedN = "cleared_total" - MetricSnapshotDurationSeconds = "snapshot_duration_seconds" - MetricBlockRepair = "block_repair_total" - MetricSyncFieldDurationSeconds = "sync_field_duration_seconds" - MetricSyncIndexDurationSeconds = "sync_index_duration_seconds" - MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" - MetricColumnAttrDiff = "ColumnAttrDiff" - MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" - MetricRowAttrDiff = "RowAttrDiff" - MetricHTTPRequest = "http_request_total" - MetricMaxShard = "maximum_shard" - MetricAntiEntropy = "antientropy_total" - MetricAntiEntropyDurationSeconds = "antientropy_duration_seconds" - MetricGarbageCollection = "garbage_collection_total" - MetricGoroutines = "goroutines" - MetricOpenFiles = "open_files" - MetricHeapAlloc = "heap_alloc" - MetricHeapInuse = "heap_inuse" - MetricStackInuse = "stack_inuse" - MetricMallocs = "mallocs" - MetricFrees = "frees" + MetricCreateIndex = "create_index_total" + MetricDeleteIndex = "delete_index_total" + MetricCreateField = "create_field_total" + MetricDeleteField = "delete_field_total" + MetricDeleteAvailableShard = "delete_available_shard_total" + MetricRecalculateCache = "recalculate_cache_total" + MetricInvalidateCache = "invalidate_cache_total" + MetricRankCacheLength = "rank_cache_length" + MetricCacheThresholdReached = "cache_threshold_reached_total" + MetricRow = "query_row_total" + MetricRowBSI = "query_row_bsi_total" + MetricSetRowAttrs = "query_setrowattrs_total" + MetricSetColumnAttrs = "query_setcolumnattrs_total" + MetricSetBit = "set_bit_total" + MetricClearBit = "clear_bit_total" + MetricImportingN = "importing_total" + MetricImportedN = "imported_total" + MetricClearingN = "clearing_total" + MetricClearedN = "cleared_total" + MetricSnapshotDurationSeconds = "snapshot_duration_seconds" + MetricBlockRepair = "block_repair_total" + MetricSyncFieldDurationSeconds = "sync_field_duration_seconds" + MetricSyncIndexDurationSeconds = "sync_index_duration_seconds" + MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" + MetricColumnAttrDiff = "ColumnAttrDiff" + MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" + MetricRowAttrDiff = "RowAttrDiff" + MetricHTTPRequest = "http_request_duration_seconds" + MetricGRPCUnaryQueryDurationSeconds = "grpc_request_pql_unary_query_duration_seconds" + MetricGRPCUnaryFormatDurationSeconds = "grpc_request_pql_unary_format_duration_seconds" + MetricGRPCStreamQueryDurationSeconds = "grpc_request_pql_stream_query_duration_seconds" + MetricGRPCStreamFormatDurationSeconds = "grpc_request_pql_stream_format_duration_seconds" + MetricMaxShard = "maximum_shard" + MetricAntiEntropy = "antientropy_total" + MetricAntiEntropyDurationSeconds = "antientropy_duration_seconds" + MetricGarbageCollection = "garbage_collection_total" + MetricGoroutines = "goroutines" + MetricOpenFiles = "open_files" + MetricHeapAlloc = "heap_alloc" + MetricHeapInuse = "heap_inuse" + MetricStackInuse = "stack_inuse" + MetricMallocs = "mallocs" + MetricFrees = "frees" ) diff --git a/server/grpc.go b/server/grpc.go index e858dee29..1bba0ce76 100644 --- a/server/grpc.go +++ b/server/grpc.go @@ -20,10 +20,12 @@ import ( "fmt" "net" "strings" + "time" "github.com/pilosa/pilosa/v2" "github.com/pilosa/pilosa/v2/logger" pb "github.com/pilosa/pilosa/v2/proto" + "github.com/pilosa/pilosa/v2/stats" "github.com/pkg/errors" "google.golang.org/grpc" "google.golang.org/grpc/codes" @@ -37,6 +39,8 @@ type grpcHandler struct { api *pilosa.API logger logger.Logger + + stats stats.StatsClient } // errorToStatusError appends an appropriate grpc status code @@ -62,16 +66,23 @@ func (h grpcHandler) QueryPQL(req *pb.QueryPQLRequest, stream pb.Pilosa_QueryPQL Index: req.Index, Query: req.Pql, } + t := time.Now() resp, err := h.api.Query(context.Background(), &query) + dur := time.Since(t) if err != nil { return errToStatusError(err) } + h.stats.Timing(pilosa.MetricGRPCStreamQueryDurationSeconds, dur, 0.1) + + t = time.Now() for row := range makeRows(resp, h.logger) { err = stream.Send(row) if err != nil { return errToStatusError(err) } } + dur = time.Since(t) + h.stats.Timing(pilosa.MetricGRPCStreamFormatDurationSeconds, dur, 0.1) return nil } @@ -82,10 +93,15 @@ func (h grpcHandler) QueryPQLUnary(ctx context.Context, req *pb.QueryPQLRequest) Index: req.Index, Query: req.Pql, } + t := time.Now() resp, err := h.api.Query(context.Background(), &query) + dur := time.Since(t) if err != nil { return nil, errToStatusError(err) } + h.stats.Timing(pilosa.MetricGRPCUnaryQueryDurationSeconds, dur, 0.1) + + t = time.Now() response := &pb.TableResponse{ Rows: make([]*pb.Row, 0), } @@ -95,6 +111,8 @@ func (h grpcHandler) QueryPQLUnary(ctx context.Context, req *pb.QueryPQLRequest) } response.Rows = append(response.Rows, &pb.Row{Columns: row.Columns}) } + dur = time.Since(t) + h.stats.Timing(pilosa.MetricGRPCUnaryFormatDurationSeconds, dur, 0.1) return response, nil } @@ -878,6 +896,7 @@ type grpcServer struct { hostPort string logger logger.Logger + stats stats.StatsClient } type grpcServerOption func(s *grpcServer) error @@ -904,6 +923,13 @@ func OptGRPCServerLogger(logger logger.Logger) grpcServerOption { } } +func OptGRPCServerStats(stats stats.StatsClient) grpcServerOption { + return func(s *grpcServer) error { + s.stats = stats + return nil + } +} + func (s *grpcServer) Serve(tlsConfig *tls.Config) error { // create listener lis, err := net.Listen("tcp", s.hostPort) @@ -920,7 +946,7 @@ func (s *grpcServer) Serve(tlsConfig *tls.Config) error { // create grpc server s.grpcServer = grpc.NewServer(opts...) - pb.RegisterPilosaServer(s.grpcServer, grpcHandler{api: s.api, logger: s.logger}) + pb.RegisterPilosaServer(s.grpcServer, grpcHandler{api: s.api, logger: s.logger, stats: s.stats}) // register the server so its services are available to grpc_cli and others reflection.Register(s.grpcServer) diff --git a/server/server.go b/server/server.go index 9d53ddf40..80fccf4f9 100644 --- a/server/server.go +++ b/server/server.go @@ -376,6 +376,7 @@ func (m *Command) SetupServer() error { OptGRPCServerAPI(m.API), OptGRPCServerURI(grpcURI), OptGRPCServerLogger(m.logger), + OptGRPCServerStats(statsClient), ) return errors.Wrap(err, "new grpc server") } From 9947c92e8e06b8f42b328d6519d64a2847eda875 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 13:26:37 -0500 Subject: [PATCH 23/26] Add stats labels and slow-query log in GRPC endpoints --- server/grpc.go | 44 ++++++++++++++++++++++++++++++++++++-------- 1 file changed, 36 insertions(+), 8 deletions(-) diff --git a/server/grpc.go b/server/grpc.go index 1bba0ce76..3e0ada18b 100644 --- a/server/grpc.go +++ b/server/grpc.go @@ -66,13 +66,18 @@ func (h grpcHandler) QueryPQL(req *pb.QueryPQLRequest, stream pb.Pilosa_QueryPQL Index: req.Index, Query: req.Pql, } + statsTags := make([]string, 0, 5) + t := time.Now() resp, err := h.api.Query(context.Background(), &query) - dur := time.Since(t) + durQuery := time.Since(t) if err != nil { return errToStatusError(err) } - h.stats.Timing(pilosa.MetricGRPCStreamQueryDurationSeconds, dur, 0.1) + longQueryTime := h.api.LongQueryTime() + if longQueryTime > 0 && durQuery > longQueryTime { + h.logger.Printf("GRPC QueryPQL %v %s", durQuery, query.Query) + } t = time.Now() for row := range makeRows(resp, h.logger) { @@ -81,8 +86,17 @@ func (h grpcHandler) QueryPQL(req *pb.QueryPQLRequest, stream pb.Pilosa_QueryPQL return errToStatusError(err) } } - dur = time.Since(t) - h.stats.Timing(pilosa.MetricGRPCStreamFormatDurationSeconds, dur, 0.1) + durFormat := time.Since(t) + if query.Remote { + statsTags = append(statsTags, "where:external") + } else { + statsTags = append(statsTags, "where:internal") + } + stats := h.stats.WithTags(statsTags...) + if stats != nil { + stats.Timing(pilosa.MetricGRPCStreamQueryDurationSeconds, durQuery, 0.1) + stats.Timing(pilosa.MetricGRPCStreamFormatDurationSeconds, durFormat, 0.1) + } return nil } @@ -93,13 +107,18 @@ func (h grpcHandler) QueryPQLUnary(ctx context.Context, req *pb.QueryPQLRequest) Index: req.Index, Query: req.Pql, } + statsTags := make([]string, 0, 5) + t := time.Now() resp, err := h.api.Query(context.Background(), &query) - dur := time.Since(t) + durQuery := time.Since(t) if err != nil { return nil, errToStatusError(err) } - h.stats.Timing(pilosa.MetricGRPCUnaryQueryDurationSeconds, dur, 0.1) + longQueryTime := h.api.LongQueryTime() + if longQueryTime > 0 && durQuery > longQueryTime { + h.logger.Printf("GRPC QueryPQLUnary %v %s", durQuery, query.Query) + } t = time.Now() response := &pb.TableResponse{ @@ -111,8 +130,17 @@ func (h grpcHandler) QueryPQLUnary(ctx context.Context, req *pb.QueryPQLRequest) } response.Rows = append(response.Rows, &pb.Row{Columns: row.Columns}) } - dur = time.Since(t) - h.stats.Timing(pilosa.MetricGRPCUnaryFormatDurationSeconds, dur, 0.1) + durFormat := time.Since(t) + if query.Remote { + statsTags = append(statsTags, "where:external") + } else { + statsTags = append(statsTags, "where:internal") + } + stats := h.stats.WithTags(statsTags...) + if stats != nil { + h.stats.Timing(pilosa.MetricGRPCUnaryQueryDurationSeconds, durQuery, 0.1) + h.stats.Timing(pilosa.MetricGRPCUnaryFormatDurationSeconds, durFormat, 0.1) + } return response, nil } From 71b976250175dbdb2bd0519ec3061ee9d4d728bc Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 16:47:15 -0500 Subject: [PATCH 24/26] Address review feedback again --- executor.go | 1 - fragment.go | 2 +- server/grpc.go | 26 ++++---------------------- 3 files changed, 5 insertions(+), 24 deletions(-) diff --git a/executor.go b/executor.go index f2cd94dff..702d0321c 100644 --- a/executor.go +++ b/executor.go @@ -2251,7 +2251,6 @@ func (e *executor) executeRowShard(ctx context.Context, index string, c *pql.Cal return rows[0], nil } row := rows[0].Union(rows[1:]...) - f.Stats.Count(MetricRow, 1, 1.0) return row, nil } diff --git a/fragment.go b/fragment.go index 285092732..78ef0597f 100644 --- a/fragment.go +++ b/fragment.go @@ -575,7 +575,7 @@ func (f *fragment) unprotectedSetBit(rowID, columnID uint64) (changed bool, err // a new copy if no one's reading it. f.rowCache.Add(rowID, nil) - f.stats.Count(MetricSetBit, 1, 0.001) + f.stats.Count(MetricSetBit, 1, 1.0) // Update row count if they have increased. if rowID > f.maxRowID { diff --git a/server/grpc.go b/server/grpc.go index 3e0ada18b..dcac5cc02 100644 --- a/server/grpc.go +++ b/server/grpc.go @@ -66,7 +66,6 @@ func (h grpcHandler) QueryPQL(req *pb.QueryPQLRequest, stream pb.Pilosa_QueryPQL Index: req.Index, Query: req.Pql, } - statsTags := make([]string, 0, 5) t := time.Now() resp, err := h.api.Query(context.Background(), &query) @@ -87,16 +86,8 @@ func (h grpcHandler) QueryPQL(req *pb.QueryPQLRequest, stream pb.Pilosa_QueryPQL } } durFormat := time.Since(t) - if query.Remote { - statsTags = append(statsTags, "where:external") - } else { - statsTags = append(statsTags, "where:internal") - } - stats := h.stats.WithTags(statsTags...) - if stats != nil { - stats.Timing(pilosa.MetricGRPCStreamQueryDurationSeconds, durQuery, 0.1) - stats.Timing(pilosa.MetricGRPCStreamFormatDurationSeconds, durFormat, 0.1) - } + h.stats.Timing(pilosa.MetricGRPCStreamQueryDurationSeconds, durQuery, 0.1) + h.stats.Timing(pilosa.MetricGRPCStreamFormatDurationSeconds, durFormat, 0.1) return nil } @@ -107,7 +98,6 @@ func (h grpcHandler) QueryPQLUnary(ctx context.Context, req *pb.QueryPQLRequest) Index: req.Index, Query: req.Pql, } - statsTags := make([]string, 0, 5) t := time.Now() resp, err := h.api.Query(context.Background(), &query) @@ -131,16 +121,8 @@ func (h grpcHandler) QueryPQLUnary(ctx context.Context, req *pb.QueryPQLRequest) response.Rows = append(response.Rows, &pb.Row{Columns: row.Columns}) } durFormat := time.Since(t) - if query.Remote { - statsTags = append(statsTags, "where:external") - } else { - statsTags = append(statsTags, "where:internal") - } - stats := h.stats.WithTags(statsTags...) - if stats != nil { - h.stats.Timing(pilosa.MetricGRPCUnaryQueryDurationSeconds, durQuery, 0.1) - h.stats.Timing(pilosa.MetricGRPCUnaryFormatDurationSeconds, durFormat, 0.1) - } + h.stats.Timing(pilosa.MetricGRPCUnaryQueryDurationSeconds, durQuery, 0.1) + h.stats.Timing(pilosa.MetricGRPCUnaryFormatDurationSeconds, durFormat, 0.1) return response, nil } From 18c6d8f76f2fca8707d70943b01f09209d921605 Mon Sep 17 00:00:00 2001 From: Alan Bernstein Date: Fri, 10 Apr 2020 18:23:00 -0500 Subject: [PATCH 25/26] Update a few metric names --- metrics.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/metrics.go b/metrics.go index 7324fdedb..c1888e0f6 100644 --- a/metrics.go +++ b/metrics.go @@ -38,10 +38,10 @@ const ( MetricBlockRepair = "block_repair_total" MetricSyncFieldDurationSeconds = "sync_field_duration_seconds" MetricSyncIndexDurationSeconds = "sync_index_duration_seconds" - MetricColumnAttrStoreBlocks = "ColumnAttrStoreBlocks" - MetricColumnAttrDiff = "ColumnAttrDiff" - MetricRowAttrStoreBlocks = "RowAttrStoreBlocks" - MetricRowAttrDiff = "RowAttrDiff" + MetricColumnAttrStoreBlocks = "column_attr_store_blocks_total" + MetricColumnAttrDiff = "column_attr_diff_total" + MetricRowAttrStoreBlocks = "row_attr_store_blocks_total" + MetricRowAttrDiff = "row_attr_diff_total" MetricHTTPRequest = "http_request_duration_seconds" MetricGRPCUnaryQueryDurationSeconds = "grpc_request_pql_unary_query_duration_seconds" MetricGRPCUnaryFormatDurationSeconds = "grpc_request_pql_unary_format_duration_seconds" From 68276159ca7f37250a81c7bb8c00cefde027a99f Mon Sep 17 00:00:00 2001 From: Matt Jaffee Date: Fri, 10 Apr 2020 21:07:43 -0500 Subject: [PATCH 26/26] don't access req.Query before knowing req is a QueryRequest --- http/handler.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/http/handler.go b/http/handler.go index 51ce25991..cecaa666e 100644 --- a/http/handler.go +++ b/http/handler.go @@ -270,10 +270,10 @@ func (h *Handler) collectStats(next http.Handler) http.Handler { longQueryTime := h.api.LongQueryTime() if longQueryTime > 0 && dur > longQueryTime { queryRequest := r.Context().Value(contextKeyQueryRequest) - req, ok := queryRequest.(*pilosa.QueryRequest) - queryString := req.Query - if !ok { - queryString = "" + + var queryString string + if req, ok := queryRequest.(*pilosa.QueryRequest); ok { + queryString = req.Query } h.logger.Printf("%s %s %v %s", r.Method, r.URL.String(), dur, queryString)