elapsed time for requests

1 files changed, 51 insertions, 3 deletions

diff --git a/cmd/rr/http/debug.go b/cmd/rr/http/debug.go
index 53980303..ae383e8d 100644
--- a/cmd/rr/http/debug.go
+++ b/cmd/rr/http/debug.go
@@ -8,7 +8,10 @@ import (
 	rr "github.com/spiral/roadrunner/cmd/rr/cmd"
 	"github.com/spiral/roadrunner/cmd/util"
 	rrhttp "github.com/spiral/roadrunner/service/http"
+	"net"
 	"net/http"
+	"strings"
+	"time"
 )
 
 func init() {
@@ -37,25 +40,31 @@ func (s *debugger) listener(event int, ctx interface{}) {
 	case rrhttp.EventResponse:
 		e := ctx.(*rrhttp.ResponseEvent)
 		s.logger.Info(util.Sprintf(
-			"<cyan+h>%s</reset> %s <white+hb>%s</reset> %s",
+			"<cyan+h>%s</reset> %s %s <white+hb>%s</reset> %s",
 			e.Request.RemoteAddr,
+			elapsed(e.Elapsed()),
 			statusColor(e.Response.Status),
 			e.Request.Method,
 			e.Request.URI,
 		))
+
 	case rrhttp.EventError:
 		e := ctx.(*rrhttp.ErrorEvent)
 
 		if _, ok := e.Error.(roadrunner.JobError); ok {
 			s.logger.Info(util.Sprintf(
-				"%s <white+hb>%s</reset> %s",
+				"<cyan+h>%s</reset> %s %s <white+hb>%s</reset> %s",
+				addr(e.Request.RemoteAddr),
+				elapsed(e.Elapsed()),
 				statusColor(500),
 				e.Request.Method,
 				uri(e.Request),
 			))
 		} else {
 			s.logger.Info(util.Sprintf(
-				"%s <white+hb>%s</reset> %s <red>%s</reset>",
+				"<cyan+h>%s</reset> %s %s <white+hb>%s</reset> %s <red>%s</reset>",
+				addr(e.Request.RemoteAddr),
+				elapsed(e.Elapsed()),
 				statusColor(500),
 				e.Request.Method,
 				uri(e.Request),
@@ -88,3 +97,42 @@ func uri(r *http.Request) string {
 
 	return fmt.Sprintf("http://%s%s", r.Host, r.URL.String())
 }
+
+// fits duration into 5 characters
+func elapsed(d time.Duration) string {
+	var v string
+	switch {
+	case d > 100*time.Second:
+		v = fmt.Sprintf("%.1fs", d.Seconds())
+	case d > 10*time.Second:
+		v = fmt.Sprintf("%.2fs", d.Seconds())
+	case d > time.Second:
+		v = fmt.Sprintf("%.3fs", d.Seconds())
+	case d > 100*time.Millisecond:
+		v = fmt.Sprintf("%.0fms", d.Seconds()*1000)
+	case d > 10*time.Millisecond:
+		v = fmt.Sprintf("%.1fms", d.Seconds()*1000)
+	default:
+		v = fmt.Sprintf("%.2fms", d.Seconds()*1000)
+	}
+
+	if d > time.Second {
+		return util.Sprintf("<red>{%v}</reset>", v)
+	}
+
+	if d > time.Millisecond*500 {
+		return util.Sprintf("<yellow>{%v}</reset>", v)
+	}
+
+	return util.Sprintf("<gray+hb>{%v}</reset>", v)
+}
+
+func addr(addr string) string {
+	// otherwise, return remote address as is
+	if !strings.ContainsRune(addr, ':') {
+		return addr
+	}
+
+	addr, _, _ = net.SplitHostPort(addr)
+	return addr
+}