From d845abb9f97211de20a54bfbf6aeb38160c17a82 Mon Sep 17 00:00:00 2001 From: stuart nelson Date: Mon, 31 Oct 2016 13:24:29 +0100 Subject: [PATCH 1/8] Add timer helper function --- prometheus/timer.go | 29 ++++++++++++++++++++++++++++ prometheus/timer_test.go | 41 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 70 insertions(+) create mode 100644 prometheus/timer.go create mode 100644 prometheus/timer_test.go diff --git a/prometheus/timer.go b/prometheus/timer.go new file mode 100644 index 0000000..31df7f8 --- /dev/null +++ b/prometheus/timer.go @@ -0,0 +1,29 @@ +// Copyright 2016 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 + +import "time" + +type Observable interface { + Observe(float64) +} + +type TimerFunc func(Observable) + +func NewTimer() TimerFunc { + begin := time.Now() + return func(obs Observable) { + obs.Observe(time.Since(begin).Seconds()) + } +} diff --git a/prometheus/timer_test.go b/prometheus/timer_test.go new file mode 100644 index 0000000..3ca7455 --- /dev/null +++ b/prometheus/timer_test.go @@ -0,0 +1,41 @@ +// Copyright 2016 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 + +import ( + "testing" + + dto "github.com/prometheus/client_model/go" +) + +func TestTimerObserve(t *testing.T) { + his := NewHistogram( + HistogramOpts{ + Name: "test_histogram", + }, + ) + + stop := NewTimer() + stop(his) + m := &dto.Metric{} + his.Write(m) + + for _, b := range m.Histogram.Bucket { + if int(b.GetCumulativeCount()) > 0 { + return + } + } + + t.Fatalf("no counts recorded") +} From 8496756f6dba0a23a5fde5bd986f4e3233e55ef6 Mon Sep 17 00:00:00 2001 From: beorn7 Date: Thu, 10 Nov 2016 18:30:43 +0100 Subject: [PATCH 2/8] Turn timer helper into a struct with methods --- prometheus/timer.go | 34 ++++++++++++++++++++++++++++------ prometheus/timer_test.go | 4 ++-- 2 files changed, 30 insertions(+), 8 deletions(-) diff --git a/prometheus/timer.go b/prometheus/timer.go index 31df7f8..f15aba2 100644 --- a/prometheus/timer.go +++ b/prometheus/timer.go @@ -15,15 +15,37 @@ package prometheus import "time" -type Observable interface { +// Observer is the interface that wraps the Observe method, used by Histogram +// and Summary to add observations. +type Observer interface { Observe(float64) } -type TimerFunc func(Observable) +type Timer struct { + begin time.Time + observer Observer + gauge Gauge +} -func NewTimer() TimerFunc { - begin := time.Now() - return func(obs Observable) { - obs.Observe(time.Since(begin).Seconds()) +func StartTimer() *Timer { + return &Timer{begin: time.Now()} +} + +func (t *Timer) With(o Observer) *Timer { + t.observer = o + return t +} + +func (t *Timer) WithGauge(g Gauge) *Timer { + t.gauge = g + return t +} + +func (t *Timer) Stop() { + if t.observer != nil { + t.observer.Observe(time.Since(t.begin).Seconds()) + } + if t.gauge != nil { + t.gauge.Set(time.Since(t.begin).Seconds()) } } diff --git a/prometheus/timer_test.go b/prometheus/timer_test.go index 3ca7455..747a7ba 100644 --- a/prometheus/timer_test.go +++ b/prometheus/timer_test.go @@ -26,8 +26,8 @@ func TestTimerObserve(t *testing.T) { }, ) - stop := NewTimer() - stop(his) + timer := StartTimer().With(his) + timer.Stop() m := &dto.Metric{} his.Write(m) From e63845e3ce999aad47ffe235605b2414ea853a2a Mon Sep 17 00:00:00 2001 From: beorn7 Date: Fri, 11 Nov 2016 12:33:56 +0100 Subject: [PATCH 3/8] Add observerFunc to observe with a Gauge --- prometheus/timer.go | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/prometheus/timer.go b/prometheus/timer.go index f15aba2..d6e0d11 100644 --- a/prometheus/timer.go +++ b/prometheus/timer.go @@ -21,10 +21,15 @@ type Observer interface { Observe(float64) } +type observerFunc func(float64) + +func (o observerFunc) Observe(value float64) { + o(value) +} + type Timer struct { begin time.Time observer Observer - gauge Gauge } func StartTimer() *Timer { @@ -37,7 +42,7 @@ func (t *Timer) With(o Observer) *Timer { } func (t *Timer) WithGauge(g Gauge) *Timer { - t.gauge = g + t.observer = observerFunc(g.Set) return t } @@ -45,7 +50,4 @@ func (t *Timer) Stop() { if t.observer != nil { t.observer.Observe(time.Since(t.begin).Seconds()) } - if t.gauge != nil { - t.gauge.Set(time.Since(t.begin).Seconds()) - } } From 120be69578d9aa4a369500f23400ad67f39296e5 Mon Sep 17 00:00:00 2001 From: beorn7 Date: Sat, 12 Nov 2016 16:13:58 +0100 Subject: [PATCH 4/8] Change timer naming from Start/Stop to New/ObserveDuration --- prometheus/timer.go | 4 ++-- prometheus/timer_test.go | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/prometheus/timer.go b/prometheus/timer.go index d6e0d11..0767281 100644 --- a/prometheus/timer.go +++ b/prometheus/timer.go @@ -32,7 +32,7 @@ type Timer struct { observer Observer } -func StartTimer() *Timer { +func NewTimer() *Timer { return &Timer{begin: time.Now()} } @@ -46,7 +46,7 @@ func (t *Timer) WithGauge(g Gauge) *Timer { return t } -func (t *Timer) Stop() { +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 747a7ba..3c117ef 100644 --- a/prometheus/timer_test.go +++ b/prometheus/timer_test.go @@ -26,8 +26,8 @@ func TestTimerObserve(t *testing.T) { }, ) - timer := StartTimer().With(his) - timer.Stop() + timer := NewTimer().With(his) + timer.ObserveDuration() m := &dto.Metric{} his.Write(m) From 8aba21aba305802c39d0f9a0bb8f93d450fc2b8d Mon Sep 17 00:00:00 2001 From: beorn7 Date: Mon, 14 Nov 2016 20:53:23 +0100 Subject: [PATCH 5/8] Completed tests --- prometheus/timer_test.go | 94 ++++++++++++++++++++++++++++++++++------ 1 file changed, 80 insertions(+), 14 deletions(-) diff --git a/prometheus/timer_test.go b/prometheus/timer_test.go index 3c117ef..ab03749 100644 --- a/prometheus/timer_test.go +++ b/prometheus/timer_test.go @@ -20,22 +20,88 @@ import ( ) func TestTimerObserve(t *testing.T) { - his := NewHistogram( - HistogramOpts{ - Name: "test_histogram", - }, - ) + 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) + defer hisTimer.ObserveDuration() + defer sumTimer.ObserveDuration() + defer gaugeTimer.ObserveDuration() + }() - timer := NewTimer().With(his) - timer.ObserveDuration() m := &dto.Metric{} his.Write(m) - - for _, b := range m.Histogram.Bucket { - if int(b.GetCumulativeCount()) > 0 { - return - } + if want, got := uint64(1), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 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) + } + m.Reset() + gauge.Write(m) + if got := m.GetGauge().GetValue(); got <= 0 { + t.Errorf("want value > 0 for gauge, got %f", got) + } +} + +func TestTimerEmpty(t *testing.T) { + emptyTimer := NewTimer() + emptyTimer.ObserveDuration() + // Do nothing, just demonstrate it works without panic. +} + +func TestTimerUnset(t *testing.T) { + his := NewHistogram(HistogramOpts{ + Name: "test_histogram", + }) + + func() { + timer := NewTimer().With(his) + defer timer.ObserveDuration() + timer.With(nil) + }() + + m := &dto.Metric{} + his.Write(m) + if want, got := uint64(0), 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() { + timer := NewTimer().With(his) + defer timer.ObserveDuration() + timer.With(sum) + }() + + m := &dto.Metric{} + his.Write(m) + if want, got := uint64(0), m.GetHistogram().GetSampleCount(); want != got { + t.Errorf("want %d observations for 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) } - - t.Fatalf("no counts recorded") } From 18c13ef63d6295f7a94ddc0654375520b062b7a5 Mon Sep 17 00:00:00 2001 From: beorn7 Date: Mon, 14 Nov 2016 20:53:36 +0100 Subject: [PATCH 6/8] Added doc comments --- prometheus/timer.go | 46 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 46 insertions(+) diff --git a/prometheus/timer.go b/prometheus/timer.go index 0767281..0c0f693 100644 --- a/prometheus/timer.go +++ b/prometheus/timer.go @@ -21,31 +21,77 @@ type Observer interface { Observe(float64) } +// observerFunc is a function that implements Observer. type observerFunc func(float64) func (o observerFunc) Observe(value float64) { o(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. 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()} } +// 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. func (t *Timer) ObserveDuration() { if t.observer != nil { t.observer.Observe(time.Since(t.begin).Seconds()) From 89ca0458cb153e446fc9021b3a3fe14f654ba3e7 Mon Sep 17 00:00:00 2001 From: beorn7 Date: Wed, 16 Nov 2016 18:17:50 +0100 Subject: [PATCH 7/8] 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) + } + } From bc365741ee18e2a81a231e672dec95321fc21dac Mon Sep 17 00:00:00 2001 From: beorn7 Date: Thu, 17 Nov 2016 12:56:06 +0100 Subject: [PATCH 8/8] Improve timer examples --- prometheus/example_timer_batch_test.go | 48 ------------------------ prometheus/example_timer_complex_test.go | 14 ++++--- prometheus/example_timer_gauge_test.go | 38 +++++++++++++++++++ prometheus/timer.go | 2 +- 4 files changed, 47 insertions(+), 55 deletions(-) delete mode 100644 prometheus/example_timer_batch_test.go create mode 100644 prometheus/example_timer_gauge_test.go diff --git a/prometheus/example_timer_batch_test.go b/prometheus/example_timer_batch_test.go deleted file mode 100644 index 1e86209..0000000 --- a/prometheus/example_timer_batch_test.go +++ /dev/null @@ -1,48 +0,0 @@ -// 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 index 692a7c4..7637880 100644 --- a/prometheus/example_timer_complex_test.go +++ b/prometheus/example_timer_complex_test.go @@ -29,7 +29,9 @@ var ( // 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. + // only where you really need separate latency tracking. Partitioning by + // status class is only an example. In concrete cases, other partitions + // might make more sense. apiRequestDuration = prometheus.NewHistogramVec( prometheus.HistogramOpts{ Name: "api_request_duration_seconds", @@ -46,15 +48,15 @@ func handler(w http.ResponseWriter, r *http.Request) { // decides wich Histogram's Observe method is called. timer := prometheus.NewTimer(prometheus.ObserverFunc(func(v float64) { switch { - case status >= http.StatusInternalServerError: + case status >= 500: // Server error. apiRequestDuration.WithLabelValues("5xx").Observe(v) - case status >= http.StatusBadRequest: + case status >= 400: // Client error. apiRequestDuration.WithLabelValues("4xx").Observe(v) - case status >= http.StatusMultipleChoices: + case status >= 300: // Redirection. apiRequestDuration.WithLabelValues("3xx").Observe(v) - case status >= http.StatusOK: + case status >= 200: // Success. apiRequestDuration.WithLabelValues("2xx").Observe(v) - default: + default: // Informational. apiRequestDuration.WithLabelValues("1xx").Observe(v) } })) diff --git a/prometheus/example_timer_gauge_test.go b/prometheus/example_timer_gauge_test.go new file mode 100644 index 0000000..dd91066 --- /dev/null +++ b/prometheus/example_timer_gauge_test.go @@ -0,0 +1,38 @@ +// 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 "github.com/prometheus/client_golang/prometheus" + +var ( + // If a function is called rarely (i.e. not more often than scrapes + // happen) or ideally only once (like in a batch job), it can make sense + // to use a Gauge for timing the function call. For timing a batch job + // and pushing the result to a Pushgateway, see also the comprehensive + // example in the push package. + funcDuration = prometheus.NewGauge(prometheus.GaugeOpts{ + Name: "example_function_duration_seconds", + Help: "Duration of the last call of an example function.", + }) +) + +func ExampleTimer_gauge() error { + // The Set method of the Gauge is used to observe the duration. + timer := prometheus.NewTimer(prometheus.ObserverFunc(funcDuration.Set)) + defer timer.ObserveDuration() + + // Do something. Return errors as encountered. The use of 'defer' above + // makes sure the function is still timed properly. + return nil +} diff --git a/prometheus/timer.go b/prometheus/timer.go index 7bd9d07..f4cac5a 100644 --- a/prometheus/timer.go +++ b/prometheus/timer.go @@ -29,7 +29,7 @@ type Observer interface { // two general use cases: // // The most common one is to use a Gauge as the Observer for a Timer. -// See the "Batch" Timer example. +// See the "Gauge" 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