From 6386f117c8d2e8341f799d8b470e34ed7afa8b2a Mon Sep 17 00:00:00 2001 From: Aliaksandr Valialkin Date: Mon, 27 Jun 2022 13:32:47 +0300 Subject: [PATCH] all: show timeRange in traces in human-readable format instead of timestamps in milliseconds --- app/vmselect/promql/eval.go | 18 +++++++++++++----- app/vmselect/promql/rollup_result_cache.go | 22 +++++++++++++++++----- docs/CHANGELOG.md | 2 ++ lib/storage/search.go | 4 +++- lib/storage/time.go | 10 +++++++++- 5 files changed, 44 insertions(+), 12 deletions(-) diff --git a/app/vmselect/promql/eval.go b/app/vmselect/promql/eval.go index e00b72d547..25c6b8528e 100644 --- a/app/vmselect/promql/eval.go +++ b/app/vmselect/promql/eval.go @@ -178,6 +178,12 @@ func (ec *EvalConfig) mayCache() bool { return true } +func (ec *EvalConfig) timeRangeString() string { + start := storage.TimestampToHumanReadableFormat(ec.Start) + end := storage.TimestampToHumanReadableFormat(ec.End) + return fmt.Sprintf("[%s..%s]", start, end) +} + func (ec *EvalConfig) getSharedTimestamps() []int64 { ec.timestampsOnce.Do(ec.timestampsInit) return ec.timestamps @@ -213,7 +219,7 @@ func evalExpr(qt *querytracer.Tracer, ec *EvalConfig, e metricsql.Expr) ([]*time if qt.Enabled() { query := e.AppendString(nil) mayCache := ec.mayCache() - qt = qt.NewChild("eval: query=%s, timeRange=[%d..%d], step=%d, mayCache=%v", query, ec.Start, ec.End, ec.Step, mayCache) + qt = qt.NewChild("eval: query=%s, timeRange=%s, step=%d, mayCache=%v", query, ec.timeRangeString(), ec.Step, mayCache) } rv, err := evalExprInternal(qt, ec, e) if err != nil { @@ -875,10 +881,12 @@ func evalRollupFuncWithMetricExpr(qt *querytracer.Tracer, ec *EvalConfig, funcNa expr metricsql.Expr, me *metricsql.MetricExpr, iafc *incrementalAggrFuncContext, windowExpr *metricsql.DurationExpr) ([]*timeseries, error) { var rollupMemorySize int64 window := windowExpr.Duration(ec.Step) - qt = qt.NewChild("rollup %s(): timeRange=[%d..%d], step=%d, window=%d", funcName, ec.Start, ec.End, ec.Step, window) - defer func() { - qt.Donef("neededMemoryBytes=%d", rollupMemorySize) - }() + if qt.Enabled() { + qt = qt.NewChild("rollup %s(): timeRange=%s, step=%d, window=%d", funcName, ec.timeRangeString(), ec.Step, window) + defer func() { + qt.Donef("neededMemoryBytes=%d", rollupMemorySize) + }() + } if me.IsEmpty() { return evalNumber(ec, nan), nil } diff --git a/app/vmselect/promql/rollup_result_cache.go b/app/vmselect/promql/rollup_result_cache.go index 6883900b03..5068e05423 100644 --- a/app/vmselect/promql/rollup_result_cache.go +++ b/app/vmselect/promql/rollup_result_cache.go @@ -156,7 +156,7 @@ func ResetRollupResultCache() { func (rrc *rollupResultCache) Get(qt *querytracer.Tracer, ec *EvalConfig, expr metricsql.Expr, window int64) (tss []*timeseries, newStart int64) { if qt.Enabled() { query := expr.AppendString(nil) - qt = qt.NewChild("rollup cache get: query=%s, timeRange=[%d..%d], step=%d, window=%d", query, ec.Start, ec.End, ec.Step, window) + qt = qt.NewChild("rollup cache get: query=%s, timeRange=%s, step=%d, window=%d", query, ec.timeRangeString(), ec.Step, window) defer qt.Done() } if !ec.mayCache() { @@ -243,7 +243,11 @@ func (rrc *rollupResultCache) Get(qt *querytracer.Tracer, ec *EvalConfig, expr m timestamps = tss[0].Timestamps newStart = timestamps[len(timestamps)-1] + ec.Step - qt.Printf("return %d series on a timeRange=[%d..%d]", len(tss), ec.Start, newStart-ec.Step) + if qt.Enabled() { + startString := storage.TimestampToHumanReadableFormat(ec.Start) + endString := storage.TimestampToHumanReadableFormat(newStart - ec.Step) + qt.Printf("return %d series on a timeRange=[%s..%s]", len(tss), startString, endString) + } return tss, newStart } @@ -252,7 +256,7 @@ var resultBufPool bytesutil.ByteBufferPool func (rrc *rollupResultCache) Put(qt *querytracer.Tracer, ec *EvalConfig, expr metricsql.Expr, window int64, tss []*timeseries) { if qt.Enabled() { query := expr.AppendString(nil) - qt = qt.NewChild("rollup cache put: query=%s, timeRange=[%d..%d], step=%d, window=%d, series=%d", query, ec.Start, ec.End, ec.Step, window, len(tss)) + qt = qt.NewChild("rollup cache put: query=%s, timeRange=%s, step=%d, window=%d, series=%d", query, ec.timeRangeString(), ec.Step, window, len(tss)) defer qt.Done() } if len(tss) == 0 || !ec.mayCache() { @@ -302,7 +306,11 @@ func (rrc *rollupResultCache) Put(qt *querytracer.Tracer, ec *EvalConfig, expr m start := timestamps[0] end := timestamps[len(timestamps)-1] if mi.CoversTimeRange(start, end) { - qt.Printf("series on the given timeRange=[%d..%d] already exist in the cache", start, end) + if qt.Enabled() { + startString := storage.TimestampToHumanReadableFormat(start) + endString := storage.TimestampToHumanReadableFormat(end) + qt.Printf("series on the given timeRange=[%s..%s] already exist in the cache", startString, endString) + } return } @@ -315,7 +323,11 @@ func (rrc *rollupResultCache) Put(qt *querytracer.Tracer, ec *EvalConfig, expr m qt.Printf("cannot store series in the cache, since they would occupy more than %d bytes", maxMarshaledSize) return } - qt.Printf("marshal %d series on a timeRange=[%d..%d] into %d bytes", len(tss), start, end, len(resultBuf.B)) + if qt.Enabled() { + startString := storage.TimestampToHumanReadableFormat(start) + endString := storage.TimestampToHumanReadableFormat(end) + qt.Printf("marshal %d series on a timeRange=[%s..%s] into %d bytes", len(tss), startString, endString, len(resultBuf.B)) + } compressedResultBuf := resultBufPool.Get() defer resultBufPool.Put(compressedResultBuf) compressedResultBuf.B = encoding.CompressZSTDLevel(compressedResultBuf.B[:0], resultBuf.B, 1) diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index f5025d3089..bf17aa482c 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -32,6 +32,8 @@ scrape_configs: - targets: ["host123:8080"] ``` +* FEATURE: [query tracing](https://docs.victoriametrics.com/Single-server-VictoriaMetrics.html#query-tracing): show timestamps in query traces in human-readable format (aka `RFC3339` in UTC timezone) instead of milliseconds since Unix epoch. For example, `2022-06-27T10:32:54.506Z` instead of `1656325974506`. + * BUGFIX: limit max memory occupied by the cache, which stores parsed regular expressions. Previously too long regular expressions passed in [MetricsQL queries](https://docs.victoriametrics.com/MetricsQL.html) could result in big amounts of used memory (e.g. multiple of gigabytes). Now the max cache size for parsed regexps is limited to a a few megabytes. * BUGFIX: [vmagent](https://docs.victoriametrics.com/vmagent.html): make sure that [stale markers](https://docs.victoriametrics.com/vmagent.html#prometheus-staleness-markers) are generated with the actual timestamp when unsuccessful scrape occurs. This should prevent from possible time series overlap on scrape target restart in dynmaic envirnoments such as Kubernetes. * BUGFIX: [VictoriaMetrics cluster](https://docs.victoriametrics.com/Cluster-VictoriaMetrics.html): assume that the response is complete if `-search.denyPartialResponse` is enabled and up to `-replicationFactor - 1` `vmstorage` nodes are unavailable. See [this issue](https://github.com/VictoriaMetrics/VictoriaMetrics/issues/1767). diff --git a/lib/storage/search.go b/lib/storage/search.go index b3da94cc55..11f9c301ad 100644 --- a/lib/storage/search.go +++ b/lib/storage/search.go @@ -383,7 +383,9 @@ func (sq *SearchQuery) String() string { for i, tfs := range sq.TagFilterss { a[i] = tagFiltersToString(tfs) } - return fmt.Sprintf("accountID=%d, projectID=%d, filters=%s, timeRange=[%d..%d]", sq.AccountID, sq.ProjectID, a, sq.MinTimestamp, sq.MaxTimestamp) + start := TimestampToHumanReadableFormat(sq.MinTimestamp) + end := TimestampToHumanReadableFormat(sq.MaxTimestamp) + return fmt.Sprintf("accountID=%d, projectID=%d, filters=%s, timeRange=[%s..%s]", sq.AccountID, sq.ProjectID, a, start, end) } func tagFiltersToString(tfs []TagFilter) string { diff --git a/lib/storage/time.go b/lib/storage/time.go index dde839f9ec..83da3db98a 100644 --- a/lib/storage/time.go +++ b/lib/storage/time.go @@ -26,7 +26,15 @@ type TimeRange struct { } func (tr *TimeRange) String() string { - return fmt.Sprintf("[%d..%d]", tr.MinTimestamp, tr.MaxTimestamp) + start := TimestampToHumanReadableFormat(tr.MinTimestamp) + end := TimestampToHumanReadableFormat(tr.MaxTimestamp) + return fmt.Sprintf("[%s..%s]", start, end) +} + +// TimestampToHumanReadableFormat converts the given timestamp to human-readable format. +func TimestampToHumanReadableFormat(timestamp int64) string { + t := timestampToTime(timestamp).UTC() + return t.Format("2006-01-02T15:04:05.999Z") } // timestampToPartitionName returns partition name for the given timestamp.