From 89ca0458cb153e446fc9021b3a3fe14f654ba3e7 Mon Sep 17 00:00:00 2001 From: beorn7 Date: Wed, 16 Nov 2016 18:17:50 +0100 Subject: [PATCH] Change the Timer API This finally makes the (presumably) common simple case as simple as it gets. The still quite common (but less common) case of using a Gauge is slightly more verbose now, but not needing to provide a separate constructor is totally worth it. Finally, the advanced use case is not really more verbose as in my original suggestion. However, the logic to decide which Observer to use is now all in the ObserverFunc handed in at construction time. This is deliberate and desired. It makes sure the selection mechanism is all spelled out there. No surprises buried deep in the function code somewhere. --- prometheus/example_timer_batch_test.go | 48 +++++++++ prometheus/example_timer_complex_test.go | 69 +++++++++++++ prometheus/example_timer_test.go | 40 ++++++++ prometheus/timer.go | 99 +++++++----------- prometheus/timer_test.go | 125 +++++++++++++++-------- 5 files changed, 279 insertions(+), 102 deletions(-) create mode 100644 prometheus/example_timer_batch_test.go create mode 100644 prometheus/example_timer_complex_test.go create mode 100644 prometheus/example_timer_test.go diff --git a/prometheus/example_timer_batch_test.go b/prometheus/example_timer_batch_test.go new file mode 100644 index 0000000..1e86209 --- /dev/null +++ b/prometheus/example_timer_batch_test.go @@ -0,0 +1,48 @@ +// Copyright 2014 The Prometheus Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package prometheus_test + +import ( + "time" + + "github.com/prometheus/client_golang/prometheus" +) + +var ( + // For periodic or batch processes that run much less frequently than + // the Prometheus scrape, it makes sense to use a Gauge to observe the + // duration. + // See https://prometheus.io/docs/practices/instrumentation/#batch-jobs + batchDuration = prometheus.NewGauge(prometheus.GaugeOpts{ + Name: "example_batch_duration_seconds", + Help: "Duration of the last batch run.", + }) +) + +func performBatch() { + // The Set method of the Gauge is used to observe the duration. + timer := prometheus.NewTimer(prometheus.ObserverFunc(batchDuration.Set)) + defer timer.ObserveDuration() + + // Actually perform the batch of work. + // ... +} + +func ExampleTimer_batch() { + // 10m is much longer than the usual scrape interval of Prometheus. + c := time.Tick(10 * time.Minute) + for _ = range c { + performBatch() + } +} diff --git a/prometheus/example_timer_complex_test.go b/prometheus/example_timer_complex_test.go new file mode 100644 index 0000000..692a7c4 --- /dev/null +++ b/prometheus/example_timer_complex_test.go @@ -0,0 +1,69 @@ +// Copyright 2014 The Prometheus Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package prometheus_test + +import ( + "net/http" + + "github.com/prometheus/client_golang/prometheus" +) + +var ( + // apiRequestDuration tracks the duration separate for each HTTP status + // class (1xx, 2xx, ...). This creates a fair amount of time series on + // the Prometheus server. Usually, you would track the duration of + // serving HTTP request without partitioning by outcome. Do something + // like this only if needed. Also note how only status classes are + // tracked, not every single status code. The latter would create an + // even larger amount of time series. Request counters partitioned by + // status code are usually OK as each counter only creates one time + // series. Histograms are way more expensive, so partition with care and + // only where you really need separate latency tracking. + apiRequestDuration = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "api_request_duration_seconds", + Help: "Histogram for the request duration of the public API, partitioned by status class.", + Buckets: prometheus.ExponentialBuckets(0.1, 1.5, 5), + }, + []string{"status_class"}, + ) +) + +func handler(w http.ResponseWriter, r *http.Request) { + status := http.StatusOK + // The ObserverFunc gets called by the deferred ObserveDuration and + // decides wich Histogram's Observe method is called. + timer := prometheus.NewTimer(prometheus.ObserverFunc(func(v float64) { + switch { + case status >= http.StatusInternalServerError: + apiRequestDuration.WithLabelValues("5xx").Observe(v) + case status >= http.StatusBadRequest: + apiRequestDuration.WithLabelValues("4xx").Observe(v) + case status >= http.StatusMultipleChoices: + apiRequestDuration.WithLabelValues("3xx").Observe(v) + case status >= http.StatusOK: + apiRequestDuration.WithLabelValues("2xx").Observe(v) + default: + apiRequestDuration.WithLabelValues("1xx").Observe(v) + } + })) + defer timer.ObserveDuration() + + // Handle the request. Set status accordingly. + // ... +} + +func ExampleTimer_complex() { + http.HandleFunc("/api", handler) +} diff --git a/prometheus/example_timer_test.go b/prometheus/example_timer_test.go new file mode 100644 index 0000000..bd86bb4 --- /dev/null +++ b/prometheus/example_timer_test.go @@ -0,0 +1,40 @@ +// Copyright 2014 The Prometheus Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package prometheus_test + +import ( + "math/rand" + "time" + + "github.com/prometheus/client_golang/prometheus" +) + +var ( + requestDuration = prometheus.NewHistogram(prometheus.HistogramOpts{ + Name: "example_request_duration_seconds", + Help: "Histogram for the runtime of a simple example function.", + Buckets: prometheus.LinearBuckets(0.01, 0.01, 10), + }) +) + +func ExampleTimer() { + // timer times this example function. It uses a Histogram, but a Summary + // would also work, as both implement Observer. Check out + // https://prometheus.io/docs/practices/histograms/ for differences. + timer := prometheus.NewTimer(requestDuration) + defer timer.ObserveDuration() + + // Do something here that takes time. + time.Sleep(time.Duration(rand.NormFloat64()*10000+50000) * time.Microsecond) +} diff --git a/prometheus/timer.go b/prometheus/timer.go index 0c0f693..7bd9d07 100644 --- a/prometheus/timer.go +++ b/prometheus/timer.go @@ -15,83 +15,58 @@ package prometheus import "time" -// Observer is the interface that wraps the Observe method, used by Histogram -// and Summary to add observations. +// Observer is the interface that wraps the Observe method, which is used by +// Histogram and Summary to add observations. type Observer interface { Observe(float64) } -// observerFunc is a function that implements Observer. -type observerFunc func(float64) +// The ObserverFunc type is an adapter to allow the use of ordinary +// functions as Observers. If f is a function with the appropriate +// signature, ObserverFunc(f) is an Observer that calls f. +// +// This adapter is usually used in connection with the Timer type, and there are +// two general use cases: +// +// The most common one is to use a Gauge as the Observer for a Timer. +// See the "Batch" Timer example. +// +// The more advanced use case is to create a function that dynamically decides +// which Observer to use for observing the duration. See the "Complex" Timer +// example. +type ObserverFunc func(float64) -func (o observerFunc) Observe(value float64) { - o(value) +// Observe calls f(value). It implements Observer. +func (f ObserverFunc) Observe(value float64) { + f(value) } // Timer is a helper type to time functions. Use NewTimer to create new -// instances. The most common usage pattern is to time a function with a -// Histogram in the following way: -// func timeMe() { -// t := NewTimer().With(myHistogram) -// defer t.ObserveDuration() -// // Do something. -// } -// See the documentation of the methods for special cases. +// instances. type Timer struct { begin time.Time observer Observer } -// NewTimer creates a new Timer. To time anything, an Observer (i.e. a Histogram -// or a Summary) or a Gague has to be bound to it, the former with the With -// method, the latter with the WithGauge method. -func NewTimer() *Timer { - return &Timer{begin: time.Now()} +// NewTimer creates a new Timer. The provided Observer is used to observe a +// duration in seconds. Timer is usually used to time a function call in the +// following way: +// func TimeMe() { +// timer := NewTimer(myHistogram) +// defer timer.ObserveDuration() +// // Do actual work. +// } +func NewTimer(o Observer) *Timer { + return &Timer{ + begin: time.Now(), + observer: o, + } } -// With binds an Observer (i.e. a Histogram or a Summary) to the Timer and -// returns the Timer for convenience. In most cases, the Observer to be used is -// already known at construction time, so it can be set immediately: -// t := NewTimer().With(myObserver) -// -// With can also be called later, to bind an Observer for the first time or to -// change the bound Observer. It can be called with nil to unbind a previously -// bound Observer. Both is useful for recording with different Observers (or -// none) depending on the outcome of the timed function. Note that timing -// depending on the outcome can be confusing and should only be used after -// careful consideration. -// -// The ObserveDuration method of the Timer records the duration by calling the -// Observe method of the bound Observer with the time elapsed since NewTimer was -// called (in seconds). -// -// Note that a Gauge bound with WithGauge overrides the Observer bound with With -// and vice versa. -func (t *Timer) With(o Observer) *Timer { - t.observer = o - return t -} - -// WithGauge binds a Gauge to the Timer and returns the Timer for -// convenience. This works in the same way as With works for Observers. To -// record the time, the Set method of the Gauge is called (with the recorded -// duration in seconds). Note that timing with Gauges is only useful for events -// that happen less frequently than the scrape interval or for one-shot batch -// jobs (where the recorded duration is pushed to a Pushgateway). -// -// Note that a Gauge bound with WithGauge overrides the Observer bound with With -// and vice versa. -func (t *Timer) WithGauge(g Gauge) *Timer { - t.observer = observerFunc(g.Set) - return t -} - -// ObserveDuration records the duration passed since NewTimer was called. If an -// Observer has been bound with the With method, ObserveDuration calls its -// Observe method with the duration in seconds as an argument. If a Gauge has -// been bound with the WithGauge method, ObserveDuration calls its Set method -// with the duration in seconds as an argument. ObserveDuration is usually -// called with a defer statement. +// ObserveDuration records the duration passed since the Timer was created with +// NewTimer. It calls the Observe method of the Observer provided during +// construction with the duration in seconds as an argument. ObserveDuration is +// usually called with a defer statement. func (t *Timer) ObserveDuration() { if t.observer != nil { t.observer.Observe(time.Since(t.begin).Seconds()) diff --git a/prometheus/timer_test.go b/prometheus/timer_test.go index ab03749..927b711 100644 --- a/prometheus/timer_test.go +++ b/prometheus/timer_test.go @@ -20,20 +20,16 @@ import ( ) func TestTimerObserve(t *testing.T) { - his := NewHistogram(HistogramOpts{ - Name: "test_histogram", - }) - sum := NewSummary(SummaryOpts{ - Name: "test_summary", - }) - gauge := NewGauge(GaugeOpts{ - Name: "test_gauge", - }) + var ( + his = NewHistogram(HistogramOpts{Name: "test_histogram"}) + sum = NewSummary(SummaryOpts{Name: "test_summary"}) + gauge = NewGauge(GaugeOpts{Name: "test_gauge"}) + ) func() { - hisTimer := NewTimer().With(his) - sumTimer := NewTimer().With(sum) - gaugeTimer := NewTimer().WithGauge(gauge) + hisTimer := NewTimer(his) + sumTimer := NewTimer(sum) + gaugeTimer := NewTimer(ObserverFunc(gauge.Set)) defer hisTimer.ObserveDuration() defer sumTimer.ObserveDuration() defer gaugeTimer.ObserveDuration() @@ -57,51 +53,100 @@ func TestTimerObserve(t *testing.T) { } func TestTimerEmpty(t *testing.T) { - emptyTimer := NewTimer() + emptyTimer := NewTimer(nil) emptyTimer.ObserveDuration() // Do nothing, just demonstrate it works without panic. } -func TestTimerUnset(t *testing.T) { - his := NewHistogram(HistogramOpts{ - Name: "test_histogram", - }) +func TestTimerConditionalTiming(t *testing.T) { + var ( + his = NewHistogram(HistogramOpts{ + Name: "test_histogram", + }) + timeMe = true + m = &dto.Metric{} + ) - func() { - timer := NewTimer().With(his) + timedFunc := func() { + timer := NewTimer(ObserverFunc(func(v float64) { + if timeMe { + his.Observe(v) + } + })) defer timer.ObserveDuration() - timer.With(nil) - }() + } - m := &dto.Metric{} + timedFunc() // This will time. his.Write(m) - if want, got := uint64(0), m.GetHistogram().GetSampleCount(); want != got { + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for histogram, got %d", want, got) + } + + timeMe = false + timedFunc() // This will not time again. + m.Reset() + his.Write(m) + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { t.Errorf("want %d observations for histogram, got %d", want, got) } } -func TestTimerChange(t *testing.T) { - his := NewHistogram(HistogramOpts{ - Name: "test_histogram", - }) - sum := NewSummary(SummaryOpts{ - Name: "test_summary", - }) +func TestTimerByOutcome(t *testing.T) { + var ( + his = NewHistogramVec( + HistogramOpts{Name: "test_histogram"}, + []string{"outcome"}, + ) + outcome = "foo" + m = &dto.Metric{} + ) - func() { - timer := NewTimer().With(his) + timedFunc := func() { + timer := NewTimer(ObserverFunc(func(v float64) { + his.WithLabelValues(outcome).Observe(v) + })) defer timer.ObserveDuration() - timer.With(sum) - }() - m := &dto.Metric{} - his.Write(m) + if outcome == "foo" { + outcome = "bar" + return + } + outcome = "foo" + } + + timedFunc() + his.WithLabelValues("foo").Write(m) if want, got := uint64(0), m.GetHistogram().GetSampleCount(); want != got { - t.Errorf("want %d observations for histogram, got %d", want, got) + t.Errorf("want %d observations for 'foo' histogram, got %d", want, got) } m.Reset() - sum.Write(m) - if want, got := uint64(1), m.GetSummary().GetSampleCount(); want != got { - t.Errorf("want %d observations for summary, got %d", want, got) + his.WithLabelValues("bar").Write(m) + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 'bar' histogram, got %d", want, got) } + + timedFunc() + m.Reset() + his.WithLabelValues("foo").Write(m) + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 'foo' histogram, got %d", want, got) + } + m.Reset() + his.WithLabelValues("bar").Write(m) + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 'bar' histogram, got %d", want, got) + } + + timedFunc() + m.Reset() + his.WithLabelValues("foo").Write(m) + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 'foo' histogram, got %d", want, got) + } + m.Reset() + his.WithLabelValues("bar").Write(m) + if want, got := uint64(2), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 'bar' histogram, got %d", want, got) + } + }