middleware/proxy: add request duration monitoring (#362)

Add a separate request duration metrics specially for proxying requests
upstream.

Fixes #259

middleware/proxy/README.md

@@ -48,6 +48,15 @@ There are three load-balancing policies available:
 All polices implement randomly spraying packets to backend hosts when *no healthy* hosts are
 available. This is to preeempt the case where the healthchecking (as a mechanism) fails.
 
+## Metrics
+
+If monitoring is enabled (via the *prometheus* directive) then the following metric is exported:
+
+* coredns_proxy_request_count_total{zone, proto, family}
+
+This has some overlap with `coredns_dns_request_count_total{zone, proto, family}`, but allows for
+specifics on upstream query resolving. See the *prometheus* documentation for more details.
+
 ## Examples
 
 Proxy all requests within example.org. to a backend system:

middleware/proxy/metrics.go

+package proxy
+
+import (
+	"sync"
+
+	"github.com/miekg/coredns/middleware"
+
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+// Metrics the proxy middleware exports.
+var (
+	RequestDuration = prometheus.NewHistogramVec(prometheus.HistogramOpts{
+		Namespace: middleware.Namespace,
+		Subsystem: subsystem,
+		Name:      "request_duration_milliseconds",
+		Buckets:   append(prometheus.DefBuckets, []float64{50, 100, 200, 500, 1000, 2000, 3000, 4000, 5000, 10000}...),
+		Help:      "Histogram of the time (in milliseconds) each request took.",
+	}, []string{"zone"})
+)
+
+// OnStartup sets up the metrics on startup.
+func OnStartup() error {
+	metricsOnce.Do(func() {
+		prometheus.MustRegister(RequestDuration)
+	})
+	return nil
+}
+
+var metricsOnce sync.Once
+
+const subsystem = "proxy"

middleware/proxy/proxy.go

@@ -74,6 +74,9 @@ func (p Proxy) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (
 		for time.Now().Sub(start) < tryDuration {
 			host := upstream.Select()
 			if host == nil {
+
+				RequestDuration.WithLabelValues(upstream.From()).Observe(float64(time.Since(start) / time.Millisecond))
+
 				return dns.RcodeServerFailure, errUnreachable
 			}
 
@@ -85,6 +88,9 @@ func (p Proxy) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (
 
 			if backendErr == nil {
 				w.WriteMsg(reply)
+
+				RequestDuration.WithLabelValues(upstream.From()).Observe(float64(time.Since(start) / time.Millisecond))
+
 				return 0, nil
 			}
 			timeout := host.FailTimeout
@@ -97,6 +103,9 @@ func (p Proxy) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (
 				atomic.AddInt32(&host.Fails, -1)
 			}(host, timeout)
 		}
+
+		RequestDuration.WithLabelValues(upstream.From()).Observe(float64(time.Since(start) / time.Millisecond))
+
 		return dns.RcodeServerFailure, errUnreachable
 	}
 	return p.Next.ServeDNS(ctx, w, r)

middleware/proxy/setup.go

@@ -23,5 +23,7 @@ func setup(c *caddy.Controller) error {
 		return Proxy{Next: next, Client: newClient(), Upstreams: upstreams}
 	})
 
+	c.OnStartup(OnStartup)
+
 	return nil
 }

test/cache_test.go

@@ -13,8 +13,6 @@ import (
 	"github.com/miekg/dns"
 )
 
-// This tests uses the exampleOrg zone as defined in proxy_test.go
-
 func TestLookupCache(t *testing.T) {
 	// Start auth. CoreDNS holding the auth zone.
 	name, rm, err := test.TempFile(".", exampleOrg)