feat(timing): timing is now working with graphite and influxdb

pkg/api/dataproxy.go

@@ -10,6 +10,7 @@ import (
 
 	"github.com/grafana/grafana/pkg/api/cloudwatch"
 	"github.com/grafana/grafana/pkg/bus"
+	"github.com/grafana/grafana/pkg/metrics"
 	"github.com/grafana/grafana/pkg/middleware"
 	m "github.com/grafana/grafana/pkg/models"
 	"github.com/grafana/grafana/pkg/setting"
@@ -80,7 +81,10 @@ func getDatasource(id int64, orgId int64) (*m.DataSource, error) {
 }
 
 func ProxyDataSourceRequest(c *middleware.Context) {
+	c.TimeRequest(metrics.M_DataSource_ProxyReq_Timer)
+
 	ds, err := getDatasource(c.ParamsInt64(":id"), c.OrgId)
+
 	if err != nil {
 		c.JsonApiErr(500, "Unable to load datasource meta data", err)
 		return

pkg/metrics/common.go

@@ -27,8 +27,17 @@ func (m *MetricMeta) Name() string {
 	return m.name
 }
 
-func (m *MetricMeta) Tags() map[string]string {
+func (m *MetricMeta) GetTagsCopy() map[string]string {
-	return m.tags
+	if len(m.tags) == 0 {
+		return make(map[string]string)
+	}
+
+	copy := make(map[string]string)
+	for k2, v2 := range m.tags {
+		copy[k2] = v2
+	}
+
+	return copy
 }
 
 func (m *MetricMeta) StringifyTags() string {
@@ -46,7 +55,7 @@ func (m *MetricMeta) StringifyTags() string {
 
 type Metric interface {
 	Name() string
-	Tags() map[string]string
+	GetTagsCopy() map[string]string
 	StringifyTags() string
 	Snapshot() Metric
 	Clear()

pkg/metrics/graphite.go

@@ -40,17 +40,23 @@ func (this *GraphitePublisher) Publish(metrics []Metric) {
 
 	buf := bytes.NewBufferString("")
 	now := time.Now().Unix()
+	addToBuf := func(metric string, value int64) {
+		buf.WriteString(fmt.Sprintf("%s %d %d\n", metric, value, now))
+	}
+
 	for _, m := range metrics {
 		metricName := this.Prefix + m.Name() + m.StringifyTags()
+		log.Info(metricName)
 
 		switch metric := m.(type) {
 		case Counter:
-			if metric.Count() > 0 {
+			addToBuf(metricName+".count", metric.Count())
-				line := fmt.Sprintf("%s %d %d\n", metricName, metric.Count(), now)
+		case Timer:
-				buf.WriteString(line)
+			addToBuf(metricName+".count", metric.Count())
-			}
+			addToBuf(metricName+".max", metric.Max())
+			addToBuf(metricName+".min", metric.Min())
+			addToBuf(metricName+".avg", metric.Avg())
 		}
-
 	}
 
 	log.Trace("Metrics: GraphitePublisher.Publish() \n%s", buf)

pkg/metrics/influxdb.go

@@ -75,17 +75,23 @@ func (this *InfluxPublisher) Publish(metrics []Metric) {
 	}
 
 	for _, m := range metrics {
-		point := client.Point{
+		tags := m.GetTagsCopy()
-			Measurement: this.prefix + m.Name(),
+		addPoint := func(name string, value int64) {
-			Tags:        m.Tags(),
+			bp.Points = append(bp.Points, client.Point{
+				Measurement: name,
+				Tags:        tags,
+				Fields:      map[string]interface{}{"value": value},
+			})
 		}
 
 		switch metric := m.(type) {
 		case Counter:
-			if metric.Count() > 0 {
+			addPoint(metric.Name()+".count", metric.Count())
-				point.Fields = map[string]interface{}{"value": metric.Count()}
+		case Timer:
-				bp.Points = append(bp.Points, point)
+			addPoint(metric.Name()+".count", metric.Count())
-			}
+			addPoint(metric.Name()+".max", metric.Max())
+			addPoint(metric.Name()+".min", metric.Min())
+			addPoint(metric.Name()+".avg", metric.Avg())
 		}
 	}
 

pkg/metrics/metric_ref.go

@@ -26,13 +26,24 @@ func RegComboCounter(name string, tagStrings ...string) Counter {
 	return cr
 }
 
-// func NewComboTimerRef(name string, tagStrings ...string) Timer {
+func RegComboTimer(name string, tagStrings ...string) Timer {
-// 	meta := NewMetricMeta(name, tagStrings)
+	meta := NewMetricMeta(name, tagStrings)
-// 	tr := &comboTimerRef{}
+	tr := &comboTimerRef{
-// 	tr.usageTimer = UsageStats.GetOrRegister(NewTimer).(Timer)
+		MetricMeta:  meta,
-// 	tr.metricTimer = MetricStats.GetOrRegister(NewTimer).(Timer)
+		usageTimer:  NewTimer(meta),
-// 	return tr
+		metricTimer: NewTimer(meta),
-// }
+	}
+
+	UsageStats.Register(tr.usageTimer)
+	MetricStats.Register(tr.metricTimer)
+	return tr
+}
+
+func RegTimer(name string, tagStrings ...string) Timer {
+	tr := NewTimer(NewMetricMeta(name, tagStrings))
+	MetricStats.Register(tr)
+	return tr
+}
 
 func (t comboTimerRef) Clear() {
 	t.metricTimer.Clear()
@@ -51,10 +62,14 @@ func (t comboTimerRef) Max() int64 {
 	panic("Avg called on combotimer ref")
 }
 
-func (t comboTimerRef) Total() int64 {
+func (t comboTimerRef) Count() int64 {
 	panic("Avg called on combotimer ref")
 }
 
+func (t comboTimerRef) Snapshot() Metric {
+	panic("Snapshot called on combotimer ref")
+}
+
 func (t comboTimerRef) AddTiming(timing int64) {
 	t.metricTimer.AddTiming(timing)
 	t.usageTimer.AddTiming(timing)

pkg/metrics/metrics.go

@@ -6,20 +6,18 @@ var MetricStats = NewRegistry()
 var (
 	M_Instance_Start = RegComboCounter("instance_start")
 
-	M_Page_Status_200 = RegComboCounter("page_resp_status", "code", "200")
+	M_Page_Status_200 = RegComboCounter("page.resp_status", "code", "200")
-	M_Page_Status_500 = RegComboCounter("page_resp_status", "code", "500")
+	M_Page_Status_500 = RegComboCounter("page.resp_status", "code", "500")
-	M_Page_Status_404 = RegComboCounter("page_resp_status", "code", "404")
+	M_Page_Status_404 = RegComboCounter("page.resp_status", "code", "404")
 
-	M_Api_Status_500 = RegComboCounter("api_resp_status", "code", "500")
+	M_Api_Status_500 = RegComboCounter("api.resp_status", "code", "500")
-	M_Api_Status_404 = RegComboCounter("api_resp_status", "code", "404")
+	M_Api_Status_404 = RegComboCounter("api.resp_status", "code", "404")
 
 	M_Api_User_SignUpStarted   = RegComboCounter("api.user.signup_started")
 	M_Api_User_SignUpCompleted = RegComboCounter("api.user.signup_completed")
 	M_Api_User_SignUpInvite    = RegComboCounter("api.user.signup_invite")
 	M_Api_Dashboard_Get        = RegComboCounter("api.dashboard.get")
 
-	// M_Api_Dashboard_Get_Timer = NewComboTimerRef("api.dashboard_load")
-
 	M_Api_Dashboard_Post    = RegComboCounter("api.dashboard.post")
 	M_Api_Admin_User_Create = RegComboCounter("api.admin.user_create")
 	M_Api_Login_Post        = RegComboCounter("api.login.post")
@@ -31,4 +29,7 @@ var (
 	M_Api_Dashboard_Snapshot_Get      = RegComboCounter("api.dashboard_snapshot.get")
 
 	M_Models_Dashboard_Insert = RegComboCounter("models.dashboard.insert")
+
+	// Timers
+	M_DataSource_ProxyReq_Timer = RegComboTimer("api.dataproxy.request.all")
 )

pkg/middleware/logger.go

@@ -21,6 +21,7 @@ import (
 	"time"
 
 	"github.com/grafana/grafana/pkg/log"
+	"github.com/grafana/grafana/pkg/metrics"
 	"github.com/grafana/grafana/pkg/setting"
 	"gopkg.in/macaron.v1"
 )
@@ -28,6 +29,7 @@ import (
 func Logger() macaron.Handler {
 	return func(res http.ResponseWriter, req *http.Request, c *macaron.Context) {
 		start := time.Now()
+		c.Data["perfmon.start"] = start
 
 		uname := c.GetCookie(setting.CookieUserName)
 		if len(uname) == 0 {
@@ -37,7 +39,13 @@ func Logger() macaron.Handler {
 		rw := res.(macaron.ResponseWriter)
 		c.Next()
 
-		content := fmt.Sprintf("Completed %s %s \"%s %s %s\" %v %s %d bytes in %dus", c.RemoteAddr(), uname, req.Method, req.URL.Path, req.Proto, rw.Status(), http.StatusText(rw.Status()), rw.Size(), time.Since(start)/time.Microsecond)
+		timeTakenMs := int64(time.Since(start) / time.Millisecond)
+		content := fmt.Sprintf("Completed %s %s \"%s %s %s\" %v %s %d bytes in %dms", c.RemoteAddr(), uname, req.Method, req.URL.Path, req.Proto, rw.Status(), http.StatusText(rw.Status()), rw.Size(), timeTakenMs)
+
+		if timer, ok := c.Data["perfmon.timer"]; ok {
+			timerTyped := timer.(metrics.Timer)
+			timerTyped.AddTiming(timeTakenMs)
+		}
 
 		switch rw.Status() {
 		case 200, 304:

pkg/middleware/middleware.go

@@ -257,3 +257,7 @@ func (ctx *Context) JsonApiErr(status int, message string, err error) {
 func (ctx *Context) HasUserRole(role m.RoleType) bool {
 	return ctx.OrgRole.Includes(role)
 }
+
+func (ctx *Context) TimeRequest(timer metrics.Timer) {
+	ctx.Data["perfmon.timer"] = timer
+}

pkg/middleware/perf.go

@@ -0,0 +1,12 @@
+package middleware
+
+import (
+	"net/http"
+
+	"gopkg.in/macaron.v1"
+)
+
+func MeasureRequestTime() macaron.Handler {
+	return func(res http.ResponseWriter, req *http.Request, c *Context) {
+	}
+}