QueryFrontend: Return server side performance information on server-timing header #3685

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.

Sign up for GitHub

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

Jump to bottom

Merged

pracucci merged 2 commits into cortexproject:master from alanprot:service-stats

Jan 26, 2021

+33 −0

Member

alanprot commented Jan 13, 2021 •

edited

Loading

What this PR does:

Creates a Util class that can be used on any handler to add server side performance information on server-timing http header
Return server-timing header with querier wall time information on query requests when -frontend.query-stats-enabled=true
Return server-timing header with request_duration on any request on query-frontend

We may want to create a config to enable this feature.

Result on chrome:

Which issue(s) this PR fixes:
Enhancement of #3595
Checklist

[✓] Tests updated
[✓] No Documentation needed
[✓] CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

pull-request-size bot added the size/L label

alanprot force-pushed the service-stats branch 3 times, most recently from a7015b0 to f625d77 Compare

January 13, 2021 22:13

alanprot changed the title ~~Service stats~~ Return server side performance information on server-timing header

alanprot changed the title ~~Return server side performance information on server-timing header~~ QueryFrontend: Return server side performance information on server-timing header

alanprot force-pushed the service-stats branch 3 times, most recently from e639cbc to 8148525 Compare

January 14, 2021 17:55

pracucci reviewed

View reviewed changes

Contributor

pracucci left a comment

Thanks @alanprot for working on this. I see a value in sending downstream this information.

However, I believe the ServiceStats is a bit over engineered for this. The Cortex philosophy is to start small and let the design evolve when new features (or changes) are introduced. In this PR you're basically introducing a framework to send generic data down to the client, while we only need to send 1 header. I would suggest to start small, remove ServiceStats and just inject the querier_wall_time with httpsnoop in the middleware. We can reconsider it and evolve the design if and when we'll need to send other information downstream.

CHANGELOG.md Show resolved Hide resolved

alanprot force-pushed the service-stats branch 10 times, most recently from 8f514a7 to 61d81d6 Compare

January 22, 2021 02:55

pracucci reviewed

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

alanprot force-pushed the service-stats branch 4 times, most recently from e8ca8d5 to 55e0a7e Compare

January 23, 2021 01:27

pracucci reviewed

View reviewed changes

Contributor

pracucci left a comment

Very good work! The new design is more lightweight and LGTM. I left a couple of questions / comments, but no hard blocker. Thanks!

integration/query_frontend_test.go Outdated

    
            @@ -302,6 +302,13 @@ func runQueryFrontendTest(t *testing.T, cfg queryFrontendTestConfig) {
          
              			assert.Equal(t, model.Time(1595846750806), matrix[0].Values[2].Timestamp)

              		}

              		// No need to repeat the test on missing metric name for each user.

Contributor

pracucci Jan 25, 2021

Suggested change

      
            		// No need to repeat the test on missing metric name for each user.
          
            		// No need to repeat the test on Server-Timing header for each user.

pkg/frontend/transport/handler.go Outdated

    
            @@ -88,7 +88,7 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
          
              	if f.cfg.QueryStatsEnabled {

              		var ctx context.Context

              		stats, ctx = querier_stats.ContextWithEmptyStats(r.Context())

              		r = r.WithContext(ctx)

              		*r = *r.WithContext(ctx)

Contributor

pracucci Jan 25, 2021

@pstibrany Do you think it's safe? I do understand why we need to do it (given the current implementation) but I've mixed feelings about manipulating the original request. Not sure it's something we've already done in other places.

Contributor

pstibrany Jan 25, 2021

This seems very brittle... it may easily break if we insert another middleware between this handler, and ServerTimingMiddleware.

We could move generation of server timing header into this handler.

Alternatively we could move stats logging into the same middleware as server-timing header.

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              func ServerTimingMiddleware(next http.Handler, statsEnabled bool) http.Handler {

              	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {

              		if !statsEnabled {

Contributor

pracucci Jan 25, 2021

Instead of doing it here, why don't we skip wrapping with ServerTimingMiddleware() at all when query stats are not enabled?

Member Author

alanprot Jan 25, 2021

Done

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              	})

              }

              func writeTimingHeader(startTime time.Time, headerWritten *bool, headers http.Header, r *http.Request) {

Contributor

pracucci Jan 25, 2021

As a best practice, I would avoid manipulating an input parameter (headerWritten in this case). You can move the if headerWritten logic out side this function, before calling writeTimingHeader().

Contributor

pstibrany Jan 25, 2021

Alternatively, make it a method of some type which will hold headerWritten value.

Member Author

alanprot Jan 25, 2021

done

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              		var (

              			headerWritten = false

              			startTime     = time.Now()

Contributor

pracucci Jan 25, 2021

We're already tracking the response time in transport.Handler. I'm wondering we should just store it in the query stats struct, so that the two values (the one logged and the one reported via HTTP header) perfectly match.

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              		parts := make([]string, 0)

              		stats := querier_stats.FromContext(r.Context())

              		if stats != nil {

              			parts = append(parts, statsValue("querier_wall_time", stats.WallTime))

Contributor

pracucci Jan 25, 2021

What's the expected unit for the duration in the Server-Timing specs? I'm asking cause we return nanoseconds and I'm wondering how it gets displayed by the browser dev tools.

Contributor

pstibrany Jan 25, 2021

It is formatted to millseconds in statsValue, which seems to be what spec is using. (Although spec is not very explicit about it, and just mentions 'ms' in examples. Weird.).

Contributor

pracucci Jan 25, 2021

Also, we should never directly read stats.WallTime but use stats.LoadWallTime().

pstibrany reviewed

View reviewed changes

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              			},

              			Write: func(next httpsnoop.WriteFunc) httpsnoop.WriteFunc {

              				return func(p []byte) (int, error) {

              					n, err := next(p)

Contributor

pstibrany Jan 25, 2021

Is this correct? If next is called first, it may start writing response, and then it will be too late to write timing header afterwards. (Unless we use Trailer, but I don't see that in this code)

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              		w = httpsnoop.Wrap(w, hooks)

              		next.ServeHTTP(w, r)

              		writeTimingHeader(startTime, &headerWritten, w.Header(), r)

Contributor

pstibrany Jan 25, 2021

Writing header after serving request seems to be too late. Under what conditions would one of WriteHeader or Write hooks not write the header already?

Member Author

alanprot Jan 25, 2021

This would happen if Write or WriteHeader is not called on any handler in the chain.

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              		parts := make([]string, 0)

              		stats := querier_stats.FromContext(r.Context())

              		if stats != nil {

              			parts = append(parts, statsValue("querier_wall_time", stats.WallTime))

Contributor

pstibrany Jan 25, 2021

It is formatted to millseconds in statsValue, which seems to be what spec is using. (Although spec is not very explicit about it, and just mentions 'ms' in examples. Weird.).

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              }

              func statsValue(name string, d time.Duration) string {

              	return name + ";dur=" + strconv.FormatInt(d.Milliseconds(), 10)

Contributor

pstibrany Jan 25, 2021

Nit: Spec allows value to be float, not just integer, if you want to use higher precision.

Member Author

alanprot Jan 25, 2021

Done

pkg/frontend/transport/server_timing_middleware.go Outdated

    
              	})

              }

              func writeTimingHeader(startTime time.Time, headerWritten *bool, headers http.Header, r *http.Request) {

Contributor

pstibrany Jan 25, 2021

Alternatively, make it a method of some type which will hold headerWritten value.

pkg/frontend/transport/handler.go Outdated

    
            @@ -88,7 +88,7 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
          
              	if f.cfg.QueryStatsEnabled {

              		var ctx context.Context

              		stats, ctx = querier_stats.ContextWithEmptyStats(r.Context())

              		r = r.WithContext(ctx)

              		*r = *r.WithContext(ctx)

Contributor

pstibrany Jan 25, 2021

This seems very brittle... it may easily break if we insert another middleware between this handler, and ServerTimingMiddleware.

We could move generation of server timing header into this handler.

Alternatively we could move stats logging into the same middleware as server-timing header.

alanprot force-pushed the service-stats branch from 55e0a7e to 0849a44 Compare

January 25, 2021 21:49

pull-request-size bot added size/M and removed size/L labels

alanprot force-pushed the service-stats branch 2 times, most recently from b75a6de to beced59 Compare

January 25, 2021 21:51


          Return server side performance metrics for query-frontend (using Serv…

257df6e

…er-timing header)

Signed-off-by: alanprot <approtas@amazon.com>

alanprot force-pushed the service-stats branch from beced59 to 257df6e Compare

January 25, 2021 22:24

pstibrany approved these changes

View reviewed changes

Contributor

pstibrany left a comment

Thank you very much!

pracucci approved these changes

View reviewed changes

Contributor

pracucci left a comment

Thanks a lot for addressing our feedback! The changeset now looks way more clean!


          Merge branch 'master' into service-stats

a330c40

pracucci merged commit 47f355d into cortexproject:master

bboreham mentioned this pull request

Support Prometheus style stats=1 query argument for PromQL requests #2498

Closed

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels