all: show timeRange in traces in human-readable format instead of timestamps in milliseconds

app/vmselect/promql/eval.go

@@ -161,6 +161,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
@@ -196,7 +202,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 {
@@ -856,10 +862,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
 	}

app/vmselect/promql/rollup_result_cache.go

@@ -202,7 +202,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() {
@@ -289,7 +289,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
 }
 
@@ -298,7 +302,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() {
@@ -348,7 +352,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
 	}
 
@@ -361,7 +369,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)

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).

lib/storage/search.go

@@ -348,7 +348,9 @@ func (sq *SearchQuery) String() string {
 	for i, tfs := range sq.TagFilterss {
 		a[i] = tagFiltersToString(tfs)
 	}
-	return fmt.Sprintf("filters=%s, timeRange=[%d..%d]", a, sq.MinTimestamp, sq.MaxTimestamp)
+	start := TimestampToHumanReadableFormat(sq.MinTimestamp)
+	end := TimestampToHumanReadableFormat(sq.MaxTimestamp)
+	return fmt.Sprintf("filters=%s, timeRange=[%s..%s]", a, start, end)
 }
 
 func tagFiltersToString(tfs []TagFilter) string {

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.