Skip to content

Commit

Permalink
QFE: only log slow query, if it is a query endpoint
Browse files Browse the repository at this point in the history
Signed-off-by: Pedro Tanaka <[email protected]>
  • Loading branch information
pedro-stanaka committed Oct 18, 2024
1 parent 731e460 commit 7c3cea7
Show file tree
Hide file tree
Showing 3 changed files with 122 additions and 1 deletion.
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ We use *breaking :warning:* to mark changes that are not backward compatible (re

### Fixed

- [#7843](https://github.com/thanos-io/thanos/pull/7843) Query Frontend: fix slow query logging for non-query endpoints.
- [#7511](https://github.com/thanos-io/thanos/pull/7511) Query Frontend: fix doubled gzip compression for response body.
- [#7592](https://github.com/thanos-io/thanos/pull/7592) Ruler: Only increment `thanos_rule_evaluation_with_warnings_total` metric for non PromQL warnings.
- [#7614](https://github.com/thanos-io/thanos/pull/7614) *: fix debug log formatting.
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
111 changes: 111 additions & 0 deletions internal/cortex/frontend/transport/handler_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,111 @@
// 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,
}
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(`{}`)),
},
}

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()
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)
}
})
}
}

0 comments on commit 7c3cea7

Please sign in to comment.