From 3065d10931d2492be17989db3ab0ef420f342d90 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torkel=20=C3=96degaard?= Date: Fri, 3 Jun 2016 09:17:36 +0200 Subject: [PATCH] feat(timing): timing is now working with graphite and influxdb --- pkg/api/dataproxy.go | 4 ++++ pkg/metrics/common.go | 15 ++++++++++++--- pkg/metrics/graphite.go | 16 +++++++++++----- pkg/metrics/influxdb.go | 20 +++++++++++++------- pkg/metrics/metric_ref.go | 31 +++++++++++++++++++++++-------- pkg/metrics/metrics.go | 15 ++++++++------- pkg/middleware/logger.go | 10 +++++++++- pkg/middleware/middleware.go | 4 ++++ pkg/middleware/perf.go | 12 ++++++++++++ 9 files changed, 96 insertions(+), 31 deletions(-) create mode 100644 pkg/middleware/perf.go diff --git a/pkg/api/dataproxy.go b/pkg/api/dataproxy.go index 9a062ddfd2d..871212adc6f 100644 --- a/pkg/api/dataproxy.go +++ b/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 diff --git a/pkg/metrics/common.go b/pkg/metrics/common.go index 69de07f6ca4..e327a081dcd 100644 --- a/pkg/metrics/common.go +++ b/pkg/metrics/common.go @@ -27,8 +27,17 @@ func (m *MetricMeta) Name() string { return m.name } -func (m *MetricMeta) Tags() map[string]string { - return m.tags +func (m *MetricMeta) GetTagsCopy() map[string]string { + 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() diff --git a/pkg/metrics/graphite.go b/pkg/metrics/graphite.go index 1d1625dfcb8..96613a63323 100644 --- a/pkg/metrics/graphite.go +++ b/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 { - line := fmt.Sprintf("%s %d %d\n", metricName, metric.Count(), now) - buf.WriteString(line) - } + addToBuf(metricName+".count", metric.Count()) + case Timer: + 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) diff --git a/pkg/metrics/influxdb.go b/pkg/metrics/influxdb.go index c6881607609..a5eb699cfda 100644 --- a/pkg/metrics/influxdb.go +++ b/pkg/metrics/influxdb.go @@ -75,17 +75,23 @@ func (this *InfluxPublisher) Publish(metrics []Metric) { } for _, m := range metrics { - point := client.Point{ - Measurement: this.prefix + m.Name(), - Tags: m.Tags(), + tags := m.GetTagsCopy() + addPoint := func(name string, value int64) { + 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 { - point.Fields = map[string]interface{}{"value": metric.Count()} - bp.Points = append(bp.Points, point) - } + addPoint(metric.Name()+".count", metric.Count()) + case Timer: + addPoint(metric.Name()+".count", metric.Count()) + addPoint(metric.Name()+".max", metric.Max()) + addPoint(metric.Name()+".min", metric.Min()) + addPoint(metric.Name()+".avg", metric.Avg()) } } diff --git a/pkg/metrics/metric_ref.go b/pkg/metrics/metric_ref.go index a4c0da09948..dcdf8af09b6 100644 --- a/pkg/metrics/metric_ref.go +++ b/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 { -// meta := NewMetricMeta(name, tagStrings) -// tr := &comboTimerRef{} -// tr.usageTimer = UsageStats.GetOrRegister(NewTimer).(Timer) -// tr.metricTimer = MetricStats.GetOrRegister(NewTimer).(Timer) -// return tr -// } +func RegComboTimer(name string, tagStrings ...string) Timer { + meta := NewMetricMeta(name, tagStrings) + tr := &comboTimerRef{ + MetricMeta: meta, + usageTimer: NewTimer(meta), + 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) diff --git a/pkg/metrics/metrics.go b/pkg/metrics/metrics.go index c5b05159a09..d88556a03b8 100644 --- a/pkg/metrics/metrics.go +++ b/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_500 = RegComboCounter("page_resp_status", "code", "500") - M_Page_Status_404 = RegComboCounter("page_resp_status", "code", "404") + M_Page_Status_200 = RegComboCounter("page.resp_status", "code", "200") + M_Page_Status_500 = RegComboCounter("page.resp_status", "code", "500") + M_Page_Status_404 = RegComboCounter("page.resp_status", "code", "404") - M_Api_Status_500 = RegComboCounter("api_resp_status", "code", "500") - M_Api_Status_404 = RegComboCounter("api_resp_status", "code", "404") + M_Api_Status_500 = RegComboCounter("api.resp_status", "code", "500") + 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") ) diff --git a/pkg/middleware/logger.go b/pkg/middleware/logger.go index 4cb8acc6354..52f319f67cd 100644 --- a/pkg/middleware/logger.go +++ b/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: diff --git a/pkg/middleware/middleware.go b/pkg/middleware/middleware.go index 7a51fd4e8d8..499435b689a 100644 --- a/pkg/middleware/middleware.go +++ b/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 +} diff --git a/pkg/middleware/perf.go b/pkg/middleware/perf.go new file mode 100644 index 00000000000..e381121a47f --- /dev/null +++ b/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) { + } +}