Merge pull request #250 from prometheus/timer-helper

Add timer helper function

prometheus/example_timer_complex_test.go

@@ -0,0 +1,71 @@
+// 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. 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",
+			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 >= 500: // Server error.
+			apiRequestDuration.WithLabelValues("5xx").Observe(v)
+		case status >= 400: // Client error.
+			apiRequestDuration.WithLabelValues("4xx").Observe(v)
+		case status >= 300: // Redirection.
+			apiRequestDuration.WithLabelValues("3xx").Observe(v)
+		case status >= 200: // Success.
+			apiRequestDuration.WithLabelValues("2xx").Observe(v)
+		default: // Informational.
+			apiRequestDuration.WithLabelValues("1xx").Observe(v)
+		}
+	}))
+	defer timer.ObserveDuration()
+
+	// Handle the request. Set status accordingly.
+	// ...
+}
+
+func ExampleTimer_complex() {
+	http.HandleFunc("/api", handler)
+}

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

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

prometheus/timer.go

@@ -0,0 +1,74 @@
+// 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"
+
+// Observer is the interface that wraps the Observe method, which is used by
+// Histogram and Summary to add observations.
+type Observer interface {
+	Observe(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 "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
+// example.
+type ObserverFunc func(float64)
+
+// 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.
+type Timer struct {
+	begin    time.Time
+	observer Observer
+}
+
+// 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,
+	}
+}
+
+// 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())
+	}
+}

prometheus/timer_test.go

@@ -0,0 +1,152 @@
+// 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) {
+	var (
+		his   = NewHistogram(HistogramOpts{Name: "test_histogram"})
+		sum   = NewSummary(SummaryOpts{Name: "test_summary"})
+		gauge = NewGauge(GaugeOpts{Name: "test_gauge"})
+	)
+
+	func() {
+		hisTimer := NewTimer(his)
+		sumTimer := NewTimer(sum)
+		gaugeTimer := NewTimer(ObserverFunc(gauge.Set))
+		defer hisTimer.ObserveDuration()
+		defer sumTimer.ObserveDuration()
+		defer gaugeTimer.ObserveDuration()
+	}()
+
+	m := &dto.Metric{}
+	his.Write(m)
+	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(nil)
+	emptyTimer.ObserveDuration()
+	// Do nothing, just demonstrate it works without panic.
+}
+
+func TestTimerConditionalTiming(t *testing.T) {
+	var (
+		his = NewHistogram(HistogramOpts{
+			Name: "test_histogram",
+		})
+		timeMe = true
+		m      = &dto.Metric{}
+	)
+
+	timedFunc := func() {
+		timer := NewTimer(ObserverFunc(func(v float64) {
+			if timeMe {
+				his.Observe(v)
+			}
+		}))
+		defer timer.ObserveDuration()
+	}
+
+	timedFunc() // This will time.
+	his.Write(m)
+	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 TestTimerByOutcome(t *testing.T) {
+	var (
+		his = NewHistogramVec(
+			HistogramOpts{Name: "test_histogram"},
+			[]string{"outcome"},
+		)
+		outcome = "foo"
+		m       = &dto.Metric{}
+	)
+
+	timedFunc := func() {
+		timer := NewTimer(ObserverFunc(func(v float64) {
+			his.WithLabelValues(outcome).Observe(v)
+		}))
+		defer timer.ObserveDuration()
+
+		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 '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(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)
+	}
+
+}