diff --git a/app/vmselect/main.go b/app/vmselect/main.go index 47edc3ca9..39abfa894 100644 --- a/app/vmselect/main.go +++ b/app/vmselect/main.go @@ -148,7 +148,7 @@ func requestHandler(w http.ResponseWriter, r *http.Request) bool { startTime := time.Now() defer requestDuration.UpdateDuration(startTime) tracerEnabled := searchutils.GetBool(r, "trace") - qt := querytracer.New(tracerEnabled) + qt := querytracer.New(tracerEnabled, r.URL.Path) // Limit the number of concurrent queries. select { diff --git a/app/vmselect/netstorage/netstorage.go b/app/vmselect/netstorage/netstorage.go index c252ffb0c..066b0674a 100644 --- a/app/vmselect/netstorage/netstorage.go +++ b/app/vmselect/netstorage/netstorage.go @@ -198,7 +198,7 @@ var resultPool sync.Pool // // rss becomes unusable after the call to RunParallel. func (rss *Results) RunParallel(qt *querytracer.Tracer, f func(rs *Result, workerID uint) error) error { - qt = qt.NewChild() + qt = qt.NewChild("parallel process of fetched data") defer func() { putTmpBlocksFile(rss.tbf) rss.tbf = nil @@ -263,7 +263,7 @@ func (rss *Results) RunParallel(qt *querytracer.Tracer, f func(rs *Result, worke close(workCh) } workChsWG.Wait() - qt.Donef("parallel process of fetched data: series=%d, samples=%d", seriesProcessedTotal, rowsProcessedTotal) + qt.Donef("series=%d, samples=%d", seriesProcessedTotal, rowsProcessedTotal) return firstErr } @@ -608,8 +608,8 @@ func (sbh *sortBlocksHeap) Pop() interface{} { // RegisterMetricNames registers metric names from mrs in the storage. func RegisterMetricNames(qt *querytracer.Tracer, at *auth.Token, mrs []storage.MetricRow, deadline searchutils.Deadline) error { - qt = qt.NewChild() - defer qt.Donef("register metric names") + qt = qt.NewChild("register metric names") + defer qt.Done() // Split mrs among available vmstorage nodes. mrsPerNode := make([][]storage.MetricRow, len(storageNodes)) for _, mr := range mrs { @@ -646,8 +646,8 @@ func RegisterMetricNames(qt *querytracer.Tracer, at *auth.Token, mrs []storage.M // DeleteSeries deletes time series matching the given sq. func DeleteSeries(qt *querytracer.Tracer, at *auth.Token, sq *storage.SearchQuery, deadline searchutils.Deadline) (int, error) { - qt = qt.NewChild() - defer qt.Donef("delete series: %s", sq) + qt = qt.NewChild("delete series: %s", sq) + defer qt.Done() requestData := sq.Marshal(nil) // Send the query to all the storage nodes in parallel. @@ -685,8 +685,8 @@ func DeleteSeries(qt *querytracer.Tracer, at *auth.Token, sq *storage.SearchQuer // GetLabelsOnTimeRange returns labels for the given tr until the given deadline. func GetLabelsOnTimeRange(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, tr storage.TimeRange, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get labels on timeRange=%s", &tr) + qt = qt.NewChild("get labels on timeRange=%s", &tr) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -740,8 +740,8 @@ func GetLabelsOnTimeRange(qt *querytracer.Tracer, at *auth.Token, denyPartialRes // GetGraphiteTags returns Graphite tags until the given deadline. func GetGraphiteTags(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, filter string, limit int, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get graphite tags: filter=%s, limit=%d", filter, limit) + qt = qt.NewChild("get graphite tags: filter=%s, limit=%d", filter, limit) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -787,8 +787,8 @@ func hasString(a []string, s string) bool { // GetLabels returns labels until the given deadline. func GetLabels(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get labels") + qt = qt.NewChild("get labels") + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -844,8 +844,8 @@ func GetLabels(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, // until the given deadline. func GetLabelValuesOnTimeRange(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, labelName string, tr storage.TimeRange, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - qt.Donef("get values for label %s on a timeRange %s", labelName, &tr) + qt = qt.NewChild("get values for label %s on a timeRange %s", labelName, &tr) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -897,8 +897,8 @@ func GetLabelValuesOnTimeRange(qt *querytracer.Tracer, at *auth.Token, denyParti // GetGraphiteTagValues returns tag values for the given tagName until the given deadline. func GetGraphiteTagValues(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, tagName, filter string, limit int, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get graphite tag values for tagName=%s, filter=%s, limit=%d", tagName, filter, limit) + qt = qt.NewChild("get graphite tag values for tagName=%s, filter=%s, limit=%d", tagName, filter, limit) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -924,8 +924,8 @@ func GetGraphiteTagValues(qt *querytracer.Tracer, at *auth.Token, denyPartialRes // GetLabelValues returns label values for the given labelName // until the given deadline. func GetLabelValues(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, labelName string, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get values for label %s", labelName) + qt = qt.NewChild("get values for label %s", labelName) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -980,8 +980,8 @@ func GetLabelValues(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse // It can be used for implementing https://graphite-api.readthedocs.io/en/latest/api.html#metrics-find func GetTagValueSuffixes(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, tr storage.TimeRange, tagKey, tagValuePrefix string, delimiter byte, deadline searchutils.Deadline) ([]string, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get tag value suffixes for tagKey=%s, tagValuePrefix=%s, timeRange=%s", tagKey, tagValuePrefix, &tr) + qt = qt.NewChild("get tag value suffixes for tagKey=%s, tagValuePrefix=%s, timeRange=%s", tagKey, tagValuePrefix, &tr) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -1029,8 +1029,8 @@ func GetTagValueSuffixes(qt *querytracer.Tracer, at *auth.Token, denyPartialResp // GetLabelEntries returns all the label entries for at until the given deadline. func GetLabelEntries(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, deadline searchutils.Deadline) ([]storage.TagEntry, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get label entries") + qt = qt.NewChild("get label entries") + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -1125,8 +1125,8 @@ func deduplicateStrings(a []string) []string { // GetTSDBStatusForDate returns tsdb status according to https://prometheus.io/docs/prometheus/latest/querying/api/#tsdb-stats func GetTSDBStatusForDate(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, deadline searchutils.Deadline, date uint64, topN, maxMetrics int) (*storage.TSDBStatus, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get tsdb stats for date=%d, topN=%d", date, topN) + qt = qt.NewChild("get tsdb stats for date=%d, topN=%d", date, topN) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -1223,8 +1223,8 @@ func toTopHeapEntries(m map[string]uint64, topN int) []storage.TopHeapEntry { // It accepts aribtrary filters on time series in sq. func GetTSDBStatusWithFilters(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, deadline searchutils.Deadline, sq *storage.SearchQuery, topN int) (*storage.TSDBStatus, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get tsdb stats: %s, topN=%d", sq, topN) + qt = qt.NewChild("get tsdb stats: %s, topN=%d", sq, topN) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -1267,8 +1267,8 @@ func GetTSDBStatusWithFilters(qt *querytracer.Tracer, at *auth.Token, denyPartia // GetSeriesCount returns the number of unique series for the given at. func GetSeriesCount(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, deadline searchutils.Deadline) (uint64, bool, error) { - qt = qt.NewChild() - defer qt.Donef("get series count") + qt = qt.NewChild("get series count") + defer qt.Done() if deadline.Exceeded() { return 0, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -1361,8 +1361,8 @@ var metricNamePool = &sync.Pool{ // It is the responsibility of f to filter blocks according to the given tr. func ExportBlocks(qt *querytracer.Tracer, at *auth.Token, sq *storage.SearchQuery, deadline searchutils.Deadline, f func(mn *storage.MetricName, b *storage.Block, tr storage.TimeRange) error) error { - qt = qt.NewChild() - defer qt.Donef("export blocks: %s", sq) + qt = qt.NewChild("export blocks: %s", sq) + defer qt.Done() if deadline.Exceeded() { return fmt.Errorf("timeout exceeded before starting data export: %s", deadline.String()) } @@ -1408,8 +1408,8 @@ func ExportBlocks(qt *querytracer.Tracer, at *auth.Token, sq *storage.SearchQuer // SearchMetricNames returns all the metric names matching sq until the given deadline. func SearchMetricNames(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, sq *storage.SearchQuery, deadline searchutils.Deadline) ([]storage.MetricName, bool, error) { - qt = qt.NewChild() - defer qt.Donef("fetch metric names: %s", sq) + qt = qt.NewChild("fetch metric names: %s", sq) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting to search metric names: %s", deadline.String()) } @@ -1467,8 +1467,8 @@ func SearchMetricNames(qt *querytracer.Tracer, at *auth.Token, denyPartialRespon // Results.RunParallel or Results.Cancel must be called on the returned Results. func ProcessSearchQuery(qt *querytracer.Tracer, at *auth.Token, denyPartialResponse bool, sq *storage.SearchQuery, fetchData bool, deadline searchutils.Deadline) (*Results, bool, error) { - qt = qt.NewChild() - defer qt.Donef("fetch matching series: %s, fetchData=%v", sq, fetchData) + qt = qt.NewChild("fetch matching series: %s, fetchData=%v", sq, fetchData) + defer qt.Done() if deadline.Exceeded() { return nil, false, fmt.Errorf("timeout exceeded before starting the query processing: %s", deadline.String()) } @@ -1573,11 +1573,11 @@ type storageNodesRequest struct { func startStorageNodesRequest(qt *querytracer.Tracer, denyPartialResponse bool, f func(qt *querytracer.Tracer, idx int, sn *storageNode) interface{}) *storageNodesRequest { resultsCh := make(chan interface{}, len(storageNodes)) for idx, sn := range storageNodes { - qtChild := qt.NewChild() + qtChild := qt.NewChild("rpc at vmstorage %s", sn.connPool.Addr()) go func(idx int, sn *storageNode) { result := f(qtChild, idx, sn) resultsCh <- result - qtChild.Donef("rpc at vmstorage %s", sn.connPool.Addr()) + qtChild.Done() }(idx, sn) } return &storageNodesRequest{ @@ -1941,9 +1941,9 @@ func (sn *storageNode) processSearchQuery(qt *querytracer.Tracer, requestData [] } func (sn *storageNode) execOnConnWithPossibleRetry(qt *querytracer.Tracer, funcName string, f func(bc *handshake.BufferedConn) error, deadline searchutils.Deadline) error { - qtChild := qt.NewChild() + qtChild := qt.NewChild("rpc call %s()", funcName) err := sn.execOnConn(qtChild, funcName, f, deadline) - qtChild.Donef("rpc call %s()", funcName) + qtChild.Done() if err == nil { return nil } @@ -1954,9 +1954,9 @@ func (sn *storageNode) execOnConnWithPossibleRetry(qt *querytracer.Tracer, funcN return err } // Repeat the query in the hope the error was temporary. - qtChild = qt.NewChild() + qtChild = qt.NewChild("retry rpc call %s() after error", funcName) err = sn.execOnConn(qtChild, funcName, f, deadline) - qtChild.Donef("retry rpc call %s() after error", funcName) + qtChild.Done() return err } diff --git a/app/vmselect/prometheus/label_values_response.qtpl b/app/vmselect/prometheus/label_values_response.qtpl index c2d92dc50..47d51b421 100644 --- a/app/vmselect/prometheus/label_values_response.qtpl +++ b/app/vmselect/prometheus/label_values_response.qtpl @@ -6,7 +6,7 @@ LabelValuesResponse generates response for /api/v1/label//values . See https://prometheus.io/docs/prometheus/latest/querying/api/#querying-label-values -{% func LabelValuesResponse(isPartial bool, labelValues []string, qt *querytracer.Tracer, qtDone func()) %} +{% func LabelValuesResponse(isPartial bool, labelValues []string, qt *querytracer.Tracer) %} { "status":"success", "isPartial":{% if isPartial %}true{% else %}false{% endif %}, @@ -18,7 +18,7 @@ See https://prometheus.io/docs/prometheus/latest/querying/api/#querying-label-va ] {% code qt.Printf("generate response for %d label values", len(labelValues)) - qtDone() + qt.Done() %} {%= dumpQueryTrace(qt) %} } diff --git a/app/vmselect/prometheus/label_values_response.qtpl.go b/app/vmselect/prometheus/label_values_response.qtpl.go index 0e8c5287b..872cda4a1 100644 --- a/app/vmselect/prometheus/label_values_response.qtpl.go +++ b/app/vmselect/prometheus/label_values_response.qtpl.go @@ -25,7 +25,7 @@ var ( ) //line app/vmselect/prometheus/label_values_response.qtpl:9 -func StreamLabelValuesResponse(qw422016 *qt422016.Writer, isPartial bool, labelValues []string, qt *querytracer.Tracer, qtDone func()) { +func StreamLabelValuesResponse(qw422016 *qt422016.Writer, isPartial bool, labelValues []string, qt *querytracer.Tracer) { //line app/vmselect/prometheus/label_values_response.qtpl:9 qw422016.N().S(`{"status":"success","isPartial":`) //line app/vmselect/prometheus/label_values_response.qtpl:12 @@ -56,7 +56,7 @@ func StreamLabelValuesResponse(qw422016 *qt422016.Writer, isPartial bool, labelV qw422016.N().S(`]`) //line app/vmselect/prometheus/label_values_response.qtpl:20 qt.Printf("generate response for %d label values", len(labelValues)) - qtDone() + qt.Done() //line app/vmselect/prometheus/label_values_response.qtpl:23 streamdumpQueryTrace(qw422016, qt) @@ -66,22 +66,22 @@ func StreamLabelValuesResponse(qw422016 *qt422016.Writer, isPartial bool, labelV } //line app/vmselect/prometheus/label_values_response.qtpl:25 -func WriteLabelValuesResponse(qq422016 qtio422016.Writer, isPartial bool, labelValues []string, qt *querytracer.Tracer, qtDone func()) { +func WriteLabelValuesResponse(qq422016 qtio422016.Writer, isPartial bool, labelValues []string, qt *querytracer.Tracer) { //line app/vmselect/prometheus/label_values_response.qtpl:25 qw422016 := qt422016.AcquireWriter(qq422016) //line app/vmselect/prometheus/label_values_response.qtpl:25 - StreamLabelValuesResponse(qw422016, isPartial, labelValues, qt, qtDone) + StreamLabelValuesResponse(qw422016, isPartial, labelValues, qt) //line app/vmselect/prometheus/label_values_response.qtpl:25 qt422016.ReleaseWriter(qw422016) //line app/vmselect/prometheus/label_values_response.qtpl:25 } //line app/vmselect/prometheus/label_values_response.qtpl:25 -func LabelValuesResponse(isPartial bool, labelValues []string, qt *querytracer.Tracer, qtDone func()) string { +func LabelValuesResponse(isPartial bool, labelValues []string, qt *querytracer.Tracer) string { //line app/vmselect/prometheus/label_values_response.qtpl:25 qb422016 := qt422016.AcquireByteBuffer() //line app/vmselect/prometheus/label_values_response.qtpl:25 - WriteLabelValuesResponse(qb422016, isPartial, labelValues, qt, qtDone) + WriteLabelValuesResponse(qb422016, isPartial, labelValues, qt) //line app/vmselect/prometheus/label_values_response.qtpl:25 qs422016 := string(qb422016.B) //line app/vmselect/prometheus/label_values_response.qtpl:25 diff --git a/app/vmselect/prometheus/labels_response.qtpl b/app/vmselect/prometheus/labels_response.qtpl index 03bf1c055..db5de3c04 100644 --- a/app/vmselect/prometheus/labels_response.qtpl +++ b/app/vmselect/prometheus/labels_response.qtpl @@ -6,7 +6,7 @@ LabelsResponse generates response for /api/v1/labels . See https://prometheus.io/docs/prometheus/latest/querying/api/#getting-label-names -{% func LabelsResponse(isPartial bool, labels []string, qt *querytracer.Tracer, qtDone func()) %} +{% func LabelsResponse(isPartial bool, labels []string, qt *querytracer.Tracer) %} { "status":"success", "isPartial":{% if isPartial %}true{% else %}false{% endif %}, @@ -18,7 +18,7 @@ See https://prometheus.io/docs/prometheus/latest/querying/api/#getting-label-nam ] {% code qt.Printf("generate response for %d labels", len(labels)) - qtDone() + qt.Done() %} {%= dumpQueryTrace(qt) %} } diff --git a/app/vmselect/prometheus/labels_response.qtpl.go b/app/vmselect/prometheus/labels_response.qtpl.go index 26ed44ce4..64b72e9d7 100644 --- a/app/vmselect/prometheus/labels_response.qtpl.go +++ b/app/vmselect/prometheus/labels_response.qtpl.go @@ -25,7 +25,7 @@ var ( ) //line app/vmselect/prometheus/labels_response.qtpl:9 -func StreamLabelsResponse(qw422016 *qt422016.Writer, isPartial bool, labels []string, qt *querytracer.Tracer, qtDone func()) { +func StreamLabelsResponse(qw422016 *qt422016.Writer, isPartial bool, labels []string, qt *querytracer.Tracer) { //line app/vmselect/prometheus/labels_response.qtpl:9 qw422016.N().S(`{"status":"success","isPartial":`) //line app/vmselect/prometheus/labels_response.qtpl:12 @@ -56,7 +56,7 @@ func StreamLabelsResponse(qw422016 *qt422016.Writer, isPartial bool, labels []st qw422016.N().S(`]`) //line app/vmselect/prometheus/labels_response.qtpl:20 qt.Printf("generate response for %d labels", len(labels)) - qtDone() + qt.Done() //line app/vmselect/prometheus/labels_response.qtpl:23 streamdumpQueryTrace(qw422016, qt) @@ -66,22 +66,22 @@ func StreamLabelsResponse(qw422016 *qt422016.Writer, isPartial bool, labels []st } //line app/vmselect/prometheus/labels_response.qtpl:25 -func WriteLabelsResponse(qq422016 qtio422016.Writer, isPartial bool, labels []string, qt *querytracer.Tracer, qtDone func()) { +func WriteLabelsResponse(qq422016 qtio422016.Writer, isPartial bool, labels []string, qt *querytracer.Tracer) { //line app/vmselect/prometheus/labels_response.qtpl:25 qw422016 := qt422016.AcquireWriter(qq422016) //line app/vmselect/prometheus/labels_response.qtpl:25 - StreamLabelsResponse(qw422016, isPartial, labels, qt, qtDone) + StreamLabelsResponse(qw422016, isPartial, labels, qt) //line app/vmselect/prometheus/labels_response.qtpl:25 qt422016.ReleaseWriter(qw422016) //line app/vmselect/prometheus/labels_response.qtpl:25 } //line app/vmselect/prometheus/labels_response.qtpl:25 -func LabelsResponse(isPartial bool, labels []string, qt *querytracer.Tracer, qtDone func()) string { +func LabelsResponse(isPartial bool, labels []string, qt *querytracer.Tracer) string { //line app/vmselect/prometheus/labels_response.qtpl:25 qb422016 := qt422016.AcquireByteBuffer() //line app/vmselect/prometheus/labels_response.qtpl:25 - WriteLabelsResponse(qb422016, isPartial, labels, qt, qtDone) + WriteLabelsResponse(qb422016, isPartial, labels, qt) //line app/vmselect/prometheus/labels_response.qtpl:25 qs422016 := string(qb422016.B) //line app/vmselect/prometheus/labels_response.qtpl:25 diff --git a/app/vmselect/prometheus/prometheus.go b/app/vmselect/prometheus/prometheus.go index a9c4f792a..0ee1204e0 100644 --- a/app/vmselect/prometheus/prometheus.go +++ b/app/vmselect/prometheus/prometheus.go @@ -375,7 +375,7 @@ func exportHandler(qt *querytracer.Tracer, at *auth.Token, w http.ResponseWriter if err != nil { return fmt.Errorf("cannot fetch data for %q: %w", sq, err) } - qtChild := qt.NewChild() + qtChild := qt.NewChild("background export format=%s", format) go func() { err := rss.RunParallel(qtChild, func(rs *netstorage.Result, workerID uint) error { if err := bw.Error(); err != nil { @@ -390,12 +390,12 @@ func exportHandler(qt *querytracer.Tracer, at *auth.Token, w http.ResponseWriter exportBlockPool.Put(xb) return nil }) - qtChild.Donef("background export format=%s", format) + qtChild.Done() close(resultsCh) doneCh <- err }() } else { - qtChild := qt.NewChild() + qtChild := qt.NewChild("background export format=%s", format) go func() { err := netstorage.ExportBlocks(qtChild, at, sq, ep.deadline, func(mn *storage.MetricName, b *storage.Block, tr storage.TimeRange) error { if err := bw.Error(); err != nil { @@ -414,7 +414,7 @@ func exportHandler(qt *querytracer.Tracer, at *auth.Token, w http.ResponseWriter exportBlockPool.Put(xb) return nil }) - qtChild.Donef("background export format=%s", format) + qtChild.Done() close(resultsCh) doneCh <- err }() @@ -596,10 +596,7 @@ func LabelValuesHandler(qt *querytracer.Tracer, startTime time.Time, at *auth.To w.Header().Set("Content-Type", "application/json") bw := bufferedwriter.Get(w) defer bufferedwriter.Put(bw) - qtDone := func() { - qt.Donef("/api/v1/labels") - } - WriteLabelValuesResponse(bw, isPartial, labelValues, qt, qtDone) + WriteLabelValuesResponse(bw, isPartial, labelValues, qt) if err := bw.Flush(); err != nil { return fmt.Errorf("canot flush label values to remote client: %w", err) } @@ -862,10 +859,7 @@ func LabelsHandler(qt *querytracer.Tracer, startTime time.Time, at *auth.Token, w.Header().Set("Content-Type", "application/json") bw := bufferedwriter.Get(w) defer bufferedwriter.Put(bw) - qtDone := func() { - qt.Donef("/api/v1/labels") - } - WriteLabelsResponse(bw, isPartial, labels, qt, qtDone) + WriteLabelsResponse(bw, isPartial, labels, qt) if err := bw.Flush(); err != nil { return fmt.Errorf("cannot send labels response to remote client: %w", err) } @@ -991,7 +985,7 @@ func SeriesHandler(qt *querytracer.Tracer, startTime time.Time, at *auth.Token, } sq := storage.NewSearchQuery(at.AccountID, at.ProjectID, start, end, tagFilterss, *maxSeriesLimit) qtDone := func() { - qt.Donef("/api/v1/series: start=%d, end=%d", start, end) + qt.Donef("start=%d, end=%d", start, end) } denyPartialResponse := searchutils.GetDenyPartialResponse(r) if end-start > 24*3600*1000 { @@ -1182,7 +1176,7 @@ func QueryHandler(qt *querytracer.Tracer, startTime time.Time, at *auth.Token, w bw := bufferedwriter.Get(w) defer bufferedwriter.Put(bw) qtDone := func() { - qt.Donef("/api/v1/query: query=%s, time=%d: series=%d", query, start, len(result)) + qt.Donef("query=%s, time=%d: series=%d", query, start, len(result)) } WriteQueryResponse(bw, ec.IsPartialResponse, result, qt, qtDone) if err := bw.Flush(); err != nil { @@ -1283,7 +1277,7 @@ func queryRangeHandler(qt *querytracer.Tracer, startTime time.Time, at *auth.Tok bw := bufferedwriter.Get(w) defer bufferedwriter.Put(bw) qtDone := func() { - qt.Donef("/api/v1/query_range: start=%d, end=%d, step=%d, query=%q: series=%d", start, end, step, query, len(result)) + qt.Donef("start=%d, end=%d, step=%d, query=%q: series=%d", start, end, step, query, len(result)) } WriteQueryRangeResponse(bw, ec.IsPartialResponse, result, qt, qtDone) if err := bw.Flush(); err != nil { diff --git a/app/vmselect/promql/eval.go b/app/vmselect/promql/eval.go index 541b25995..e00b72d54 100644 --- a/app/vmselect/promql/eval.go +++ b/app/vmselect/promql/eval.go @@ -210,22 +210,23 @@ func getTimestamps(start, end, step int64) []int64 { } func evalExpr(qt *querytracer.Tracer, ec *EvalConfig, e metricsql.Expr) ([]*timeseries, error) { - qt = qt.NewChild() + 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) + } rv, err := evalExprInternal(qt, ec, e) if err != nil { return nil, err } if qt.Enabled() { - query := e.AppendString(nil) seriesCount := len(rv) pointsPerSeries := 0 if len(rv) > 0 { pointsPerSeries = len(rv[0].Timestamps) } pointsCount := seriesCount * pointsPerSeries - mayCache := ec.mayCache() - qt.Donef("eval: query=%s, timeRange=[%d..%d], step=%d, mayCache=%v: series=%d, points=%d, pointsPerSeries=%d", - query, ec.Start, ec.End, ec.Step, mayCache, seriesCount, pointsCount, pointsPerSeries) + qt.Donef("series=%d, points=%d, pointsPerSeries=%d", seriesCount, pointsCount, pointsPerSeries) } return rv, nil } @@ -251,9 +252,9 @@ func evalExprInternal(qt *querytracer.Tracer, ec *EvalConfig, e metricsql.Expr) if fe, ok := e.(*metricsql.FuncExpr); ok { nrf := getRollupFunc(fe.Name) if nrf == nil { - qtChild := qt.NewChild() + qtChild := qt.NewChild("transform %s()", fe.Name) rv, err := evalTransformFunc(qtChild, ec, fe) - qtChild.Donef("transform %s(): series=%d", fe.Name, len(rv)) + qtChild.Donef("series=%d", len(rv)) return rv, err } args, re, err := evalRollupFuncArgs(qt, ec, fe) @@ -271,15 +272,15 @@ func evalExprInternal(qt *querytracer.Tracer, ec *EvalConfig, e metricsql.Expr) return rv, nil } if ae, ok := e.(*metricsql.AggrFuncExpr); ok { - qtChild := qt.NewChild() + qtChild := qt.NewChild("aggregate %s()", ae.Name) rv, err := evalAggrFunc(qtChild, ec, ae) - qtChild.Donef("aggregate %s(): series=%d", ae.Name, len(rv)) + qtChild.Donef("series=%d", len(rv)) return rv, err } if be, ok := e.(*metricsql.BinaryOpExpr); ok { - qtChild := qt.NewChild() + qtChild := qt.NewChild("binary op %q", be.Op) rv, err := evalBinaryOp(qtChild, ec, be) - qtChild.Donef("binary op %q: series=%d", be.Op, len(rv)) + qtChild.Donef("series=%d", len(rv)) return rv, err } if ne, ok := e.(*metricsql.NumberExpr); ok { @@ -742,8 +743,8 @@ func aggregateAbsentOverTime(ec *EvalConfig, expr metricsql.Expr, tss []*timeser func evalRollupFuncWithSubquery(qt *querytracer.Tracer, ec *EvalConfig, funcName string, rf rollupFunc, expr metricsql.Expr, re *metricsql.RollupExpr) ([]*timeseries, error) { // TODO: determine whether to use rollupResultCacheV here. - qt = qt.NewChild() - defer qt.Donef("subquery") + qt = qt.NewChild("subquery") + defer qt.Done() step := re.Step.Duration(ec.Step) if step == 0 { step = ec.Step @@ -874,9 +875,9 @@ 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() + qt = qt.NewChild("rollup %s(): timeRange=[%d..%d], step=%d, window=%d", funcName, ec.Start, ec.End, ec.Step, window) defer func() { - qt.Donef("rollup %s(): timeRange=[%d..%d], step=%d, window=%d, neededMemoryBytes=%d", funcName, ec.Start, ec.End, ec.Step, window, rollupMemorySize) + qt.Donef("neededMemoryBytes=%d", rollupMemorySize) }() if me.IsEmpty() { return evalNumber(ec, nan), nil @@ -994,8 +995,8 @@ func getRollupMemoryLimiter() *memoryLimiter { func evalRollupWithIncrementalAggregate(qt *querytracer.Tracer, funcName string, keepMetricNames bool, iafc *incrementalAggrFuncContext, rss *netstorage.Results, rcs []*rollupConfig, preFunc func(values []float64, timestamps []int64), sharedTimestamps []int64) ([]*timeseries, error) { - qt = qt.NewChild() - defer qt.Donef("rollup %s() with incremental aggregation %s() over %d series", funcName, iafc.ae.Name, rss.Len()) + qt = qt.NewChild("rollup %s() with incremental aggregation %s() over %d series", funcName, iafc.ae.Name, rss.Len()) + defer qt.Done() err := rss.RunParallel(qt, func(rs *netstorage.Result, workerID uint) error { rs.Values, rs.Timestamps = dropStaleNaNs(funcName, rs.Values, rs.Timestamps) preFunc(rs.Values, rs.Timestamps) @@ -1029,8 +1030,8 @@ func evalRollupWithIncrementalAggregate(qt *querytracer.Tracer, funcName string, func evalRollupNoIncrementalAggregate(qt *querytracer.Tracer, funcName string, keepMetricNames bool, rss *netstorage.Results, rcs []*rollupConfig, preFunc func(values []float64, timestamps []int64), sharedTimestamps []int64) ([]*timeseries, error) { - qt = qt.NewChild() - defer qt.Donef("rollup %s() over %d series", funcName, rss.Len()) + qt = qt.NewChild("rollup %s() over %d series", funcName, rss.Len()) + defer qt.Done() tss := make([]*timeseries, 0, rss.Len()*len(rcs)) var tssLock sync.Mutex err := rss.RunParallel(qt, func(rs *netstorage.Result, workerID uint) error { diff --git a/app/vmselect/promql/rollup_result_cache.go b/app/vmselect/promql/rollup_result_cache.go index 4d5eb0360..6883900b0 100644 --- a/app/vmselect/promql/rollup_result_cache.go +++ b/app/vmselect/promql/rollup_result_cache.go @@ -154,10 +154,10 @@ func ResetRollupResultCache() { } func (rrc *rollupResultCache) Get(qt *querytracer.Tracer, ec *EvalConfig, expr metricsql.Expr, window int64) (tss []*timeseries, newStart int64) { - qt = qt.NewChild() if qt.Enabled() { query := expr.AppendString(nil) - defer qt.Donef("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=[%d..%d], step=%d, window=%d", query, ec.Start, ec.End, ec.Step, window) + defer qt.Done() } if !ec.mayCache() { qt.Printf("do not fetch series from cache, since it is disabled in the current context") @@ -250,10 +250,10 @@ func (rrc *rollupResultCache) Get(qt *querytracer.Tracer, ec *EvalConfig, expr m var resultBufPool bytesutil.ByteBufferPool func (rrc *rollupResultCache) Put(qt *querytracer.Tracer, ec *EvalConfig, expr metricsql.Expr, window int64, tss []*timeseries) { - qt = qt.NewChild() if qt.Enabled() { query := expr.AppendString(nil) - defer qt.Donef("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=[%d..%d], step=%d, window=%d, series=%d", query, ec.Start, ec.End, ec.Step, window, len(tss)) + defer qt.Done() } if len(tss) == 0 || !ec.mayCache() { qt.Printf("do not store series to cache, since it is disabled in the current context") diff --git a/app/vmstorage/transport/server.go b/app/vmstorage/transport/server.go index 7e8f4b0d3..9bf8e8273 100644 --- a/app/vmstorage/transport/server.go +++ b/app/vmstorage/transport/server.go @@ -482,7 +482,7 @@ func (s *Server) processVMSelectRequest(ctx *vmselectRequestCtx) error { if err != nil { return fmt.Errorf("cannot read traceEnabled: %w", err) } - ctx.qt = querytracer.New(traceEnabled) + ctx.qt = querytracer.New(traceEnabled, "%s() at vmstorage", rpcName) // Limit the time required for reading request args. if err := ctx.bc.SetReadDeadline(time.Now().Add(5 * time.Second)); err != nil { @@ -506,7 +506,7 @@ func (s *Server) processVMSelectRequest(ctx *vmselectRequestCtx) error { } // Finish query trace. - ctx.qt.Donef("%s() at vmstorage", rpcName) + ctx.qt.Done() traceJSON := ctx.qt.ToJSON() if err := ctx.writeString(traceJSON); err != nil { return fmt.Errorf("cannot send trace with length %d bytes to vmselect: %w", len(traceJSON), err) diff --git a/docs/README.md b/docs/README.md index d126a4861..084367ee3 100644 --- a/docs/README.md +++ b/docs/README.md @@ -1425,7 +1425,7 @@ In this case VictoriaMetrics puts query trace into `trace` field in the output J For example, the following command: ```bash -curl http://localhost:8428/api/v1/query_range -d 'query=2*rand()' -d 'start=-1h' -d 'step=1m' -d 'trace=1' | jq -r '.trace' +curl http://localhost:8428/api/v1/query_range -d 'query=2*rand()' -d 'start=-1h' -d 'step=1m' -d 'trace=1' | jq '.trace' ``` would return the following trace: diff --git a/docs/Single-server-VictoriaMetrics.md b/docs/Single-server-VictoriaMetrics.md index e47210099..c6b8e65c3 100644 --- a/docs/Single-server-VictoriaMetrics.md +++ b/docs/Single-server-VictoriaMetrics.md @@ -1429,7 +1429,7 @@ In this case VictoriaMetrics puts query trace into `trace` field in the output J For example, the following command: ```bash -curl http://localhost:8428/api/v1/query_range -d 'query=2*rand()' -d 'start=-1h' -d 'step=1m' -d 'trace=1' | jq -r '.trace' +curl http://localhost:8428/api/v1/query_range -d 'query=2*rand()' -d 'start=-1h' -d 'step=1m' -d 'trace=1' | jq '.trace' ``` would return the following trace: diff --git a/lib/querytracer/tracer.go b/lib/querytracer/tracer.go index 0e22234c3..a6467973a 100644 --- a/lib/querytracer/tracer.go +++ b/lib/querytracer/tracer.go @@ -15,16 +15,16 @@ var denyQueryTracing = flag.Bool("denyQueryTracing", false, "Whether to disable // Tracer represents query tracer. // // It must be created via New call. -// Each created tracer must be finalized via Donef call. +// Each created tracer must be finalized via Done or Donef call. // // Tracer may contain sub-tracers (branches) in order to build tree-like execution order. // Call Tracer.NewChild func for adding sub-tracer. type Tracer struct { // startTime is the time when Tracer was created startTime time.Time - // doneTime is the time when Donef was called + // doneTime is the time when Done or Donef was called doneTime time.Time - // message is the message generated by Printf or Donef call. + // message is the message generated by NewChild, Printf or Donef call. message string // children is a list of children Tracer objects children []*Tracer @@ -33,16 +33,17 @@ type Tracer struct { span *span } -// New creates a new instance of the tracer. +// New creates a new instance of the tracer with the given fmt.Sprintf(format, args...) message. // // If enabled isn't set, then all function calls to the returned object will be no-op. // -// Donef must be called when the tracer should be finished. -func New(enabled bool) *Tracer { +// Done or Donef must be called when the tracer should be finished. +func New(enabled bool, format string, args ...interface{}) *Tracer { if *denyQueryTracing || !enabled { return nil } return &Tracer{ + message: fmt.Sprintf(format, args...), startTime: time.Now(), } } @@ -52,26 +53,43 @@ func (t *Tracer) Enabled() bool { return t != nil } -// NewChild adds a new child Tracer to t. +// NewChild adds a new child Tracer to t with the given fmt.Sprintf(format, args...) message. +// +// The returned child must be closed via Done or Donef calls. // // NewChild cannot be called from concurrent goroutines. // Create children tracers from a single goroutine and then pass them // to concurrent goroutines. -func (t *Tracer) NewChild() *Tracer { +func (t *Tracer) NewChild(format string, args ...interface{}) *Tracer { if t == nil { return nil } - if t.message != "" { + if !t.doneTime.IsZero() { panic(fmt.Errorf("BUG: NewChild() cannot be called after Donef(%q) call", t.message)) } child := &Tracer{ + message: fmt.Sprintf(format, args...), startTime: time.Now(), } t.children = append(t.children, child) return child } -// Donef finishes t. +// Done finishes t. +// +// Done cannot be called multiple times. +// Other Tracer functions cannot be called after Done call. +func (t *Tracer) Done() { + if t == nil { + return + } + if !t.doneTime.IsZero() { + panic(fmt.Errorf("BUG: Donef(%q) already called", t.message)) + } + t.doneTime = time.Now() +} + +// Donef appends the given fmt.Sprintf(format, args..) message to t and finished it. // // Donef cannot be called multiple times. // Other Tracer functions cannot be called after Donef call. @@ -79,21 +97,21 @@ func (t *Tracer) Donef(format string, args ...interface{}) { if t == nil { return } - if t.message != "" { - panic(fmt.Errorf("BUG: Donef() already called with message %q", t.message)) + if !t.doneTime.IsZero() { + panic(fmt.Errorf("BUG: Donef(%q) already called", t.message)) } - t.message = fmt.Sprintf(format, args...) + t.message += ": " + fmt.Sprintf(format, args...) t.doneTime = time.Now() } -// Printf adds new message to t. +// Printf adds new fmt.Sprintf(format, args...) message to t. // // Printf cannot be called from concurrent goroutines. func (t *Tracer) Printf(format string, args ...interface{}) { if t == nil { return } - if t.message != "" { + if !t.doneTime.IsZero() { panic(fmt.Errorf("BUG: Printf() cannot be called after Done(%q) call", t.message)) } now := time.Now() @@ -177,8 +195,8 @@ func (t *Tracer) toSpanInternal(prevTime time.Time) (*span, time.Time) { // tracer with children msg := t.message doneTime := t.doneTime - if msg == "" { - msg = "missing Tracer.Donef() call" + if doneTime.IsZero() { + msg += ": missing Tracer.Done() call" doneTime = t.getLastChildDoneTime(t.startTime) } d := doneTime.Sub(t.startTime) diff --git a/lib/querytracer/tracer_test.go b/lib/querytracer/tracer_test.go index 8e8660aa5..fa278d2b7 100644 --- a/lib/querytracer/tracer_test.go +++ b/lib/querytracer/tracer_test.go @@ -6,21 +6,21 @@ import ( ) func TestTracerDisabled(t *testing.T) { - qt := New(false) + qt := New(false, "test") if qt.Enabled() { t.Fatalf("query tracer must be disabled") } - qtChild := qt.NewChild() + qtChild := qt.NewChild("child done %d", 456) if qtChild.Enabled() { t.Fatalf("query tracer must be disabled") } qtChild.Printf("foo %d", 123) - qtChild.Donef("child done %d", 456) + qtChild.Done() qt.Printf("parent %d", 789) if err := qt.AddJSON([]byte("foobar")); err != nil { t.Fatalf("unexpected error in AddJSON: %s", err) } - qt.Donef("test") + qt.Done() s := qt.String() if s != "" { t.Fatalf("unexpected trace; got %s; want empty", s) @@ -32,20 +32,20 @@ func TestTracerDisabled(t *testing.T) { } func TestTracerEnabled(t *testing.T) { - qt := New(true) + qt := New(true, "test") if !qt.Enabled() { t.Fatalf("query tracer must be enabled") } - qtChild := qt.NewChild() + qtChild := qt.NewChild("child done %d", 456) if !qtChild.Enabled() { t.Fatalf("child query tracer must be enabled") } qtChild.Printf("foo %d", 123) - qtChild.Donef("child done %d", 456) + qtChild.Done() qt.Printf("parent %d", 789) - qt.Donef("test") + qt.Donef("foo %d", 33) s := qt.String() - sExpected := `- 0ms: test + sExpected := `- 0ms: test: foo 33 | - 0ms: child done 456 | | - 0ms: foo 123 | - 0ms: parent 789 @@ -56,9 +56,9 @@ func TestTracerEnabled(t *testing.T) { } func TestTracerMultiline(t *testing.T) { - qt := New(true) + qt := New(true, "line1\nline2") qt.Printf("line3\nline4\n") - qt.Donef("line1\nline2") + qt.Done() s := qt.String() sExpected := `- 0ms: line1 | line2 @@ -71,18 +71,18 @@ func TestTracerMultiline(t *testing.T) { } func TestTracerToJSON(t *testing.T) { - qt := New(true) + qt := New(true, "test") if !qt.Enabled() { t.Fatalf("query tracer must be enabled") } - qtChild := qt.NewChild() + qtChild := qt.NewChild("child done %d", 456) if !qtChild.Enabled() { t.Fatalf("child query tracer must be enabled") } qtChild.Printf("foo %d", 123) - qtChild.Donef("child done %d", 456) + qtChild.Done() qt.Printf("parent %d", 789) - qt.Donef("test") + qt.Done() s := qt.ToJSON() sExpected := `{"duration_msec":0,"message":"test","children":[` + `{"duration_msec":0,"message":"child done 456","children":[` + @@ -94,11 +94,11 @@ func TestTracerToJSON(t *testing.T) { } func TestTraceAddJSON(t *testing.T) { - qtChild := New(true) + qtChild := New(true, "child") qtChild.Printf("foo") - qtChild.Donef("child") + qtChild.Done() jsonTrace := qtChild.ToJSON() - qt := New(true) + qt := New(true, "parent") qt.Printf("first_line") if err := qt.AddJSON([]byte(jsonTrace)); err != nil { t.Fatalf("unexpected error in AddJSON: %s", err) @@ -107,7 +107,7 @@ func TestTraceAddJSON(t *testing.T) { if err := qt.AddJSON(nil); err != nil { t.Fatalf("unexpected error in AddJSON(nil): %s", err) } - qt.Donef("parent") + qt.Done() s := qt.String() sExpected := `- 0ms: parent | - 0ms: first_line @@ -131,15 +131,15 @@ func TestTraceAddJSON(t *testing.T) { } func TestTraceMissingDonef(t *testing.T) { - qt := New(true) + qt := New(true, "parent") qt.Printf("parent printf") - qtChild := qt.NewChild() + qtChild := qt.NewChild("child") qtChild.Printf("child printf") qt.Printf("another parent printf") s := qt.String() - sExpected := `- 0ms: missing Tracer.Donef() call + sExpected := `- 0ms: parent: missing Tracer.Done() call | - 0ms: parent printf -| - 0ms: missing Tracer.Donef() call +| - 0ms: child: missing Tracer.Done() call | | - 0ms: child printf | - 0ms: another parent printf ` diff --git a/lib/storage/search.go b/lib/storage/search.go index de92757f9..b3da94cc5 100644 --- a/lib/storage/search.go +++ b/lib/storage/search.go @@ -171,8 +171,8 @@ func (s *Search) reset() { // // Init returns the upper bound on the number of found time series. func (s *Search) Init(qt *querytracer.Tracer, storage *Storage, tfss []*TagFilters, tr TimeRange, maxMetrics int, deadline uint64) int { - qt = qt.NewChild() - defer qt.Donef("init series search: filters=%s, timeRange=%s", tfss, &tr) + qt = qt.NewChild("init series search: filters=%s, timeRange=%s", tfss, &tr) + defer qt.Done() if s.needClosing { logger.Panicf("BUG: missing MustClose call before the next call to Init") } diff --git a/lib/storage/storage.go b/lib/storage/storage.go index 8d3b33427..ced5866b8 100644 --- a/lib/storage/storage.go +++ b/lib/storage/storage.go @@ -1124,8 +1124,8 @@ func nextRetentionDuration(retentionMsecs int64) time.Duration { // SearchMetricNames returns metric names matching the given tfss on the given tr. func (s *Storage) SearchMetricNames(qt *querytracer.Tracer, tfss []*TagFilters, tr TimeRange, maxMetrics int, deadline uint64) ([]MetricName, error) { - qt = qt.NewChild() - defer qt.Donef("search for matching metric names") + qt = qt.NewChild("search for matching metric names") + defer qt.Done() tsids, err := s.searchTSIDs(qt, tfss, tr, maxMetrics, deadline) if err != nil { return nil, err @@ -1169,8 +1169,8 @@ func (s *Storage) SearchMetricNames(qt *querytracer.Tracer, tfss []*TagFilters, // searchTSIDs returns sorted TSIDs for the given tfss and the given tr. func (s *Storage) searchTSIDs(qt *querytracer.Tracer, tfss []*TagFilters, tr TimeRange, maxMetrics int, deadline uint64) ([]TSID, error) { - qt = qt.NewChild() - defer qt.Donef("search for matching series ids") + qt = qt.NewChild("search for matching series ids") + defer qt.Done() // Do not cache tfss -> tsids here, since the caching is performed // on idb level. @@ -1221,8 +1221,8 @@ var ( // // This should speed-up further searchMetricNameWithCache calls for metricIDs from tsids. func (s *Storage) prefetchMetricNames(qt *querytracer.Tracer, tsids []TSID, deadline uint64) error { - qt = qt.NewChild() - defer qt.Donef("prefetch metric names for %d series ids", len(tsids)) + qt = qt.NewChild("prefetch metric names for %d series ids", len(tsids)) + defer qt.Done() if len(tsids) == 0 { qt.Printf("nothing to prefetch") return nil