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