refactor: 调整Server-Timing的生成处理

httplog/httplog.go

@@ -257,8 +257,8 @@ func Format(ctx *fasthttp.RequestCtx, tags []*Tag, startedAt time.Time) []byte {
 		case latency:
 			return []byte(time.Since(startedAt).String())
 		case latencyMs:
-			offset := (time.Now().UnixNano() - startedAt.UnixNano()) / (1000 * 1000)
-			return []byte(strconv.FormatInt(offset, 10))
+			ms := util.GetTimeConsuming(startedAt)
+			return []byte(strconv.Itoa(ms))
 		default:
 			return tag.data
 		}

proxy/proxy.go

@@ -5,10 +5,12 @@ import (
 	"crypto/sha1"
 	"encoding/base64"
 	"fmt"
+	"strconv"
 	"sync/atomic"
 	"time"
 
 	"github.com/valyala/fasthttp"
+	"github.com/vicanso/pike/util"
 	"github.com/vicanso/pike/vars"
 )
 
@@ -44,6 +46,12 @@ func RegisterPolicy(name string, policy func(string) Policy) {
 
 // Do 将当前请求转发至upstream
 func Do(ctx *fasthttp.RequestCtx, us *Upstream, config *Config) (*fasthttp.Response, error) {
+	reqHeader := &ctx.Request.Header
+	startedAt := time.Now()
+	defer func() {
+		ms := util.GetTimeConsuming(startedAt)
+		reqHeader.SetCanonical(vars.TimingFetch, []byte(strconv.Itoa(ms)))
+	}()
 	policy := us.Policy
 	uh := policy.Select(us.Hosts, ctx)
 	if uh == nil {
@@ -54,7 +62,6 @@ func Do(ctx *fasthttp.RequestCtx, us *Upstream, config *Config) (*fasthttp.Respo
 
 	// 设置x-forwarded-for
 	xFor := vars.XForwardedFor
-	reqHeader := &ctx.Request.Header
 	orginalXFor := reqHeader.PeekBytes(xFor)
 
 	ip := []byte(ctx.RemoteIP().String())

server/server.go

@@ -111,23 +111,33 @@ func doProxy(ctx *fasthttp.RequestCtx, us *proxy.Upstream, conf *Config) (*fasth
 	return resp, header, body, nil
 }
 
+func getTimingDesc(ms, name string) []byte {
+	if len(ms) == 0 {
+		return nil
+	}
+	return []byte("0=" + ms + ";" + name)
+}
+
 // 设置响应的 Server-Timing
 func setServerTiming(ctx *fasthttp.RequestCtx, startedAt time.Time) {
-	v := startedAt.UnixNano()
-	now := time.Now().UnixNano()
-	use := int((now - v) / 1000000)
-	desc := []byte("0=" + strconv.Itoa(use) + ";" + string(vars.Name))
 	header := &ctx.Response.Header
+	reqHeader := &ctx.Request.Header
+	ms := util.GetTimeConsuming(startedAt)
+	totalDesc := getTimingDesc(strconv.Itoa(ms), string(vars.Name))
+	fetchDesc := getTimingDesc(string(reqHeader.PeekBytes(vars.TimingFetch)), string(vars.Name)+"-fetch")
+	gzipDesc := getTimingDesc(string(reqHeader.PeekBytes(vars.TimingGzip)), string(vars.Name)+"-gzip")
+
+	timing := [][]byte{
+		totalDesc,
+		fetchDesc,
+		gzipDesc,
+	}
 
 	serverTiming := header.PeekBytes(vars.ServerTiming)
-	if len(serverTiming) == 0 {
-		header.SetCanonical(vars.ServerTiming, desc)
-	} else {
-		header.SetCanonical(vars.ServerTiming, bytes.Join([][]byte{
-			desc,
-			serverTiming,
-		}, []byte(",")))
+	if len(serverTiming) != 0 {
+		timing = append(timing, serverTiming)
 	}
+	header.SetCanonical(vars.ServerTiming, bytes.Join(timing, []byte(",")))
 }
 
 // 增加额外的 Response Header
@@ -288,7 +298,9 @@ func handler(ctx *fasthttp.RequestCtx, conf *Config) {
 		// 不可缓存的数据，`dispatch.Response`函数会根据客户端来决定是否压缩
 		shouldDoCompress := shouldCompress(&resp.Header)
 		if shouldDoCompress && cacheAge > 0 && len(body) > vars.CompressMinLength {
+			gzipStartedAt := time.Now()
 			gzipData, err := util.Gzip(body)
+			util.SetTimingConsumingHeader(gzipStartedAt, &ctx.Request.Header, vars.TimingGzip)
 			if err == nil {
 				body = gzipData
 				compressType = vars.GzipData

util/util.go

@@ -7,6 +7,8 @@ import (
 	"expvar"
 	"fmt"
 	"io/ioutil"
+	"strconv"
+	"time"
 
 	"github.com/valyala/fasthttp"
 	"github.com/vicanso/pike/vars"
@@ -65,3 +67,16 @@ func GetDebugVars() []byte {
 	w.Flush()
 	return b.Bytes()
 }
+
+// GetTimeConsuming 获取使用耗时(ms)
+func GetTimeConsuming(startedAt time.Time) int {
+	v := startedAt.UnixNano()
+	now := time.Now().UnixNano()
+	return int((now - v) / 1000000)
+}
+
+// SetTimingConsumingHeader 设置耗时至http头
+func SetTimingConsumingHeader(startedAt time.Time, header *fasthttp.RequestHeader, key []byte) {
+	ms := GetTimeConsuming(startedAt)
+	header.SetCanonical(key, []byte(strconv.Itoa(ms)))
+}

util/util_test.go

@@ -2,6 +2,7 @@ package util
 
 import (
 	"testing"
+	"time"
 
 	"github.com/valyala/fasthttp"
 )
@@ -40,3 +41,20 @@ func TestGetDebugVars(t *testing.T) {
 		t.Fatalf("get the debug vars fail, %v", string(buf))
 	}
 }
+
+func TestGetTimeConsuming(t *testing.T) {
+	startedAt := time.Now()
+	time.Sleep(2 * time.Millisecond)
+	ms := GetTimeConsuming(startedAt)
+	if ms <= 0 {
+		t.Fatalf("the time consuming should be gt 0")
+	}
+}
+
+func TestTimingConsumingHeader(t *testing.T) {
+	header := &fasthttp.RequestHeader{}
+	startedAt := time.Now()
+	time.Sleep(2 * time.Millisecond)
+	key := []byte("Consuming")
+	SetTimingConsumingHeader(startedAt, header, key)
+}

vars/const.go

@@ -48,18 +48,21 @@ var (
 
 	// Gzip gzip compress
 	Gzip = []byte("gzip")
-
 	// Deflate deflate compress
 	Deflate = []byte("deflate")
-
 	// Br brotli compress
 	Br = []byte("br")
 
+	// TimingFetch fecth time
+	TimingFetch = []byte("Timing-Fetch")
+	// TimingGzip gzip time
+	TimingGzip = []byte("Timing-Gzip")
+
 	// Get http get method
 	Get = []byte("GET")
-
 	// Head http head method
 	Head = []byte("HEAD")
+
 	// LineBreak 换行符
 	LineBreak = []byte("\r\n")
 	// Colon 冒号