Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

QFE: only log slow query, if it is a query endpoint #7843

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ We use *breaking :warning:* to mark changes that are not backward compatible (re
- [#7814](https://github.com/thanos-io/thanos/pull/7814) Store: label_values: if matchers contain **name**=="something", do not add <labelname> != "" to fetch less postings.
- [#7679](https://github.com/thanos-io/thanos/pull/7679) Query: respect store.limit.* flags when evaluating queries
- [#7821](https://github.com/thanos-io/thanos/pull/7679) Query/Receive: Fix coroutine leak introduced in https://github.com/thanos-io/thanos/pull/7796.
- [#7843](https://github.com/thanos-io/thanos/pull/7843) Query Frontend: fix slow query logging for non-query endpoints.

### Added
- [#7763](https://github.com/thanos-io/thanos/pull/7763) Ruler: use native histograms for client latency metrics.
Expand Down
11 changes: 10 additions & 1 deletion internal/cortex/frontend/transport/handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -148,7 +148,9 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
}

// Check whether we should parse the query string.
shouldReportSlowQuery := f.cfg.LogQueriesLongerThan != 0 && queryResponseTime > f.cfg.LogQueriesLongerThan
shouldReportSlowQuery := f.cfg.LogQueriesLongerThan != 0 &&
queryResponseTime > f.cfg.LogQueriesLongerThan &&
isQueryEndpoint(r.URL.Path)
if shouldReportSlowQuery || f.cfg.QueryStatsEnabled {
queryString = f.parseRequestQueryString(r, buf)
}
Expand All @@ -161,6 +163,13 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
}
}

// isQueryEndpoint returns true if the path is any of the Prometheus HTTP API,
// query-related endpoints.
// Example: /api/v1/query, /api/v1/query_range, /api/v1/series, /api/v1/label, /api/v1/labels
func isQueryEndpoint(path string) bool {
return strings.HasPrefix(path, "/api/v1")
}

// reportSlowQuery reports slow queries.
func (f *Handler) reportSlowQuery(r *http.Request, responseHeaders http.Header, queryString url.Values, queryResponseTime time.Duration) {
// NOTE(GiedriusS): see https://github.com/grafana/grafana/pull/60301 for more info.
Expand Down
112 changes: 112 additions & 0 deletions internal/cortex/frontend/transport/handler_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,112 @@
// Copyright (c) The Cortex Authors.
// Licensed under the Apache License 2.0.

package transport

import (
"bytes"
"io"
"net/http"
"net/http/httptest"
"testing"
"time"

"github.com/go-kit/log"
"github.com/prometheus/client_golang/prometheus"
"github.com/stretchr/testify/require"
)

type fakeRoundTripper struct {
response *http.Response
err error
requestLatency time.Duration
}

func (f *fakeRoundTripper) RoundTrip(_ *http.Request) (*http.Response, error) {
time.Sleep(f.requestLatency)
return f.response, f.err
}

func TestHandler_SlowQueryLog(t *testing.T) {
t.Parallel()

cfg := HandlerConfig{
QueryStatsEnabled: true,
LogQueriesLongerThan: 1 * time.Microsecond,
}

tests := []struct {
name string
url string
logParts []string
}{
{
name: "Basic query",
url: "/api/v1/query?query=absent(up)&start=1714262400&end=1714266000",
logParts: []string{
"slow query detected",
"time_taken=",
"path=/api/v1/query",
"param_query=absent(up)",
"param_start=1714262400",
"param_end=1714266000",
},
},
{
name: "Series call",
url: "/api/v1/series?match[]={__name__=~\"up\"}",
logParts: []string{
"slow query detected",
"time_taken=",
"path=/api/v1/series",
},
},
{
name: "Query with different parameters",
url: "/api/v1/query_range?query=rate(http_requests_total[5m])&start=1714262400&end=1714266000&step=15",
logParts: []string{
"slow query detected",
"time_taken=",
"path=/api/v1/query_range",
"param_query=rate(http_requests_total[5m])",
"param_start=1714262400",
"param_end=1714266000",
"param_step=15",
},
},
{
name: "Non-query endpoint",
url: "/favicon.ico",
// No slow query log for non-query endpoints
logParts: []string{},
},
}

for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
t.Parallel()
fakeRoundTripper := &fakeRoundTripper{
requestLatency: 2 * time.Microsecond,
response: &http.Response{
StatusCode: http.StatusOK,
Header: http.Header{
"Content-Type": []string{"application/json"},
"Server-Timing": []string{"querier;dur=1.23"},
},
Body: io.NopCloser(bytes.NewBufferString(`{}`)),
},
}

logWriter := &bytes.Buffer{}
logger := log.NewLogfmtLogger(log.NewSyncWriter(logWriter))

handler := NewHandler(cfg, fakeRoundTripper, logger, prometheus.NewRegistry())

handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", tt.url, nil))

for _, part := range tt.logParts {
require.Contains(t, logWriter.String(), part)
}
})
}
}
Loading