performance tuning (#277)

* lazy build string

* avoid build string

* add option to disable access log

* improve metrics performance

* make code clean

* improve time related performance

* lazy build log message

* remove some memory alloc

* use sync.Pool for filter stat

* updated according to comments

pkg/context/contexttest/context.go

@@ -43,11 +43,9 @@ type MockedHTTPContext struct {
  MockedCancel func(err error)
  MockedCancelled func() bool
  MockedClientDisconnected func() bool
- MockedDuration func() time.Duration
  MockedOnFinish func(func())
  MockedAddTag func(tag string)
  MockedStatMetric func() *httpstat.Metric
- MockedLog func() string
  MockedFinish func()
  MockedTemplate func() texttemplate.TemplateEngine
  MockedSetTemplate func(ht *context.HTTPTemplate)
@@ -144,14 +142,6 @@ func (c *MockedHTTPContext) ClientDisconnected() bool {
  return false
 }
 
-// Duration mocks the Duration function of HTTPContext
-func (c *MockedHTTPContext) Duration() time.Duration {
- if c.MockedDuration != nil {
- return c.MockedDuration()
- }
- return 0
-}
-
 // OnFinish mocks the OnFinish function of HTTPContext
 func (c *MockedHTTPContext) OnFinish(fn func()) {
  if c.MockedFinish != nil {
@@ -177,14 +167,6 @@ func (c *MockedHTTPContext) StatMetric() *httpstat.Metric {
  return nil
 }
 
-// Log mocks the Log function of HTTPContext
-func (c *MockedHTTPContext) Log() string {
- if c.MockedLog != nil {
- return c.MockedLog()
- }
- return ""
-}
-
 // Finish mocks the Finish function of HTTPContext
 func (c *MockedHTTPContext) Finish() {
  if c.MockedFinish != nil {

pkg/context/httpcontext.go

@@ -27,15 +27,13 @@ import (
  "sync"
  "time"
 
- "github.com/opentracing/opentracing-go"
-
  "github.com/megaease/easegress/pkg/logger"
  "github.com/megaease/easegress/pkg/tracing"
+ "github.com/megaease/easegress/pkg/util/fasttime"
  "github.com/megaease/easegress/pkg/util/httpheader"
  "github.com/megaease/easegress/pkg/util/httpstat"
  "github.com/megaease/easegress/pkg/util/stringtool"
  "github.com/megaease/easegress/pkg/util/texttemplate"
- "github.com/megaease/easegress/pkg/util/timetool"
 )
 
 type (
@@ -59,12 +57,10 @@ type (
  Cancelled() bool
  ClientDisconnected() bool
 
- Duration() time.Duration // For log, sample, etc.
- OnFinish(func()) // For setting final client statistics, etc.
- AddTag(tag string) // For debug, log, etc.
+ OnFinish(func()) // For setting final client statistics, etc.
+ AddTag(tag string) // For debug, log, etc.
 
  StatMetric() *httpstat.Metric
- Log() string
 
  Finish()
 
@@ -134,8 +130,7 @@ type (
  httpContext struct {
  mutex sync.Mutex
 
- startTime *time.Time
- endTime *time.Time
+ startTime time.Time
  finishFuncs []FinishFunc
  tags []string
  caller HandlerCaller
@@ -144,12 +139,13 @@ type (
  w *httpResponse
 
  ht *HTTPTemplate
- tracer opentracing.Tracer
  span tracing.Span
  originalReqCtx stdcontext.Context
  stdctx stdcontext.Context
  cancelFunc stdcontext.CancelFunc
  err error
+
+ metric httpstat.Metric
  }
 )
 
@@ -162,17 +158,15 @@ func New(stdw http.ResponseWriter, stdr *http.Request,
  stdctx, cancelFunc := stdcontext.WithCancel(originalReqCtx)
  stdr = stdr.WithContext(stdctx)
 
- startTime := time.Now()
+ startTime := fasttime.Now()
  return &httpContext{
- startTime: &startTime,
- tracer: tracer,
- span: tracing.NewSpan(tracer, spanName),
+ startTime: startTime,
+ span: tracing.NewSpanWithStart(tracer, spanName, startTime),
  originalReqCtx: originalReqCtx,
  stdctx: stdctx,
  cancelFunc: cancelFunc,
  r: newHTTPRequest(stdr),
  w: newHTTPResponse(stdw, stdr),
- ht: NewHTTPTemplateDummy(),
  }
 }
 
@@ -244,14 +238,6 @@ func (ctx *httpContext) Cancelled() bool {
  return ctx.err != nil || ctx.stdctx.Err() != nil
 }
 
-func (ctx *httpContext) Duration() time.Duration {
- if ctx.endTime != nil {
- return ctx.endTime.Sub(*ctx.startTime)
- }
-
- return time.Now().Sub(*ctx.startTime)
-}
-
 func (ctx *httpContext) ClientDisconnected() bool {
  return ctx.originalReqCtx.Err() != nil
 }
@@ -266,8 +252,10 @@ func (ctx *httpContext) Finish() {
  ctx.r.finish()
  ctx.w.finish()
 
- endTime := time.Now()
- ctx.endTime = &endTime
+ ctx.metric.StatusCode = ctx.Response().StatusCode()
+ ctx.metric.Duration = fasttime.Now().Sub(ctx.startTime)
+ ctx.metric.ReqSize = ctx.Request().Size()
+ ctx.metric.RespSize = ctx.Response().Size()
 
  for _, fn := range ctx.finishFuncs {
  func() {
@@ -282,39 +270,29 @@ func (ctx *httpContext) Finish() {
  }()
  }
 
- logger.HTTPAccess(ctx.Log())
+ logger.LazyHTTPAccess(func() string {
+ stdr := ctx.r.std
+
+ // log format:
+ // [startTime]
+ // [requestInfo]
+ // [contextStatistics]
+ // [tags]
+ //
+ // [$startTime]
+ // [$remoteAddr $realIP $method $requestURL $proto $statusCode]
+ // [$contextDuration $readBytes $writeBytes]
+ // [$tags]
+ return fmt.Sprintf("[%s] [%s %s %s %s %s %d] [%v rx:%dB tx:%dB] [%s]",
+ fasttime.Format(ctx.startTime, fasttime.RFC3339Milli),
+ stdr.RemoteAddr, ctx.r.RealIP(), stdr.Method, stdr.RequestURI, stdr.Proto, ctx.w.code,
+ ctx.metric.Duration, ctx.r.Size(), ctx.w.Size(),
+ strings.Join(ctx.tags, " | "))
+ })
 }
 
 func (ctx *httpContext) StatMetric() *httpstat.Metric {
- return &httpstat.Metric{
- StatusCode: ctx.Response().StatusCode(),
- Duration: ctx.Duration(),
- ReqSize: ctx.Request().Size(),
- RespSize: ctx.Response().Size(),
- }
-}
-
-func (ctx *httpContext) Log() string {
- stdr := ctx.r.std
-
- // log format:
- // [startTime]
- // [requestInfo]
- // [contextStatistics]
- // [tags]
- //
- // [$startTime]
- // [$remoteAddr $realIP $method $requestURL $proto $statusCode]
- // [$contextDuration $readBytes $writeBytes]
- // [$tags]
- return fmt.Sprintf("[%s] "+
- "[%s %s %s %s %s %d] "+
- "[%v rx:%dB tx:%dB] "+
- "[%s]",
- ctx.startTime.Format(timetool.RFC3339Milli),
- stdr.RemoteAddr, ctx.r.RealIP(), stdr.Method, stdr.RequestURI, stdr.Proto, ctx.w.code,
- ctx.Duration(), ctx.r.Size(), ctx.w.Size(),
- strings.Join(ctx.tags, " | "))
+ return &ctx.metric
 }
 
 // Template returns the template engine

pkg/context/httprequest.go

@@ -25,7 +25,6 @@ import (
 
  "github.com/megaease/easegress/pkg/util/callbackreader"
  "github.com/megaease/easegress/pkg/util/httpheader"
- "github.com/megaease/easegress/pkg/util/stringtool"
 )
 
 type (
@@ -67,12 +66,19 @@ func newHTTPRequest(stdr *http.Request) *httpRequest {
  })
 
  // Reference: https://tools.ietf.org/html/rfc2616#section-5
- // NOTE: We don't use httputil.DumpRequest because it does not
- // completely output plain HTTP Request.
- meta := stringtool.Cat(stdr.Method, " ", stdr.URL.RequestURI(), " ", stdr.Proto, "\r\n",
- hq.Header().Dump(), "\r\n\r\n")
+ //
+ // meta length is the length of:
+ // w.stdr.Method + " "
+ // + stdr.URL.RequestURI() + " "
+ // + stdr.Proto + "\r\n",
+ // + w.Header().Dump() + "\r\n\r\n"
+ //
+ // but to improve performance, we won't build this string
 
- hq.metaSize = len(meta)
+ hq.metaSize += len(stdr.Method) + 1
+ hq.metaSize += len(stdr.URL.RequestURI()) + 1
+ hq.metaSize += len(stdr.Proto) + 2
+ hq.metaSize += hq.Header().Length() + 4
 
  return hq
 }

pkg/context/httpresponse.go

@@ -26,7 +26,6 @@ import (
 
  "github.com/megaease/easegress/pkg/logger"
  "github.com/megaease/easegress/pkg/util/httpheader"
- "github.com/megaease/easegress/pkg/util/stringtool"
 )
 
 var bodyFlushBuffSize = 8 * int64(os.Getpagesize())
@@ -166,17 +165,33 @@ func (w *httpResponse) finish() {
 }
 
 func (w *httpResponse) Size() uint64 {
+ size := int(w.bodyWritten)
+
  text := http.StatusText(w.StatusCode())
  if text == "" {
  text = "status code " + strconv.Itoa(w.StatusCode())
  }
 
  // Reference: https://tools.ietf.org/html/rfc2616#section-6
- // NOTE: We don't use httputil.DumpResponse because it does not
- // completely output plain HTTP Request.
- meta := stringtool.Cat(w.stdr.Proto, " ", strconv.Itoa(w.StatusCode()), " ", text, "\r\n",
- w.Header().Dump(), "\r\n\r\n")
- return uint64(len(meta)) + w.bodyWritten
+ //
+ // meta length is the length of:
+ // w.stdr.Proto + " "
+ // + strconv.Itoa(w.StatusCode()) + " "
+ // + text + "\r\n",
+ // + w.Header().Dump() + "\r\n\r\n"
+ //
+ // but to improve performance, we won't build this string
+
+ size += len(w.stdr.Proto) + 1
+ if c := w.StatusCode(); c >= 100 && c < 1000 {
+ size += 3 + 1
+ } else {
+ size += len(strconv.Itoa(w.StatusCode())) + 1
+ }
+ size += len(text) + 2
+ size += w.Header().Length() + 4
+
+ return uint64(size)
 }
 
 func (w *httpResponse) Std() http.ResponseWriter {

pkg/context/httptemplate.go

@@ -175,14 +175,6 @@ func NewHTTPTemplate(filterBuffs []FilterBuff) (*HTTPTemplate, error) {
  return &e, nil
 }
 
-// NewHTTPTemplateDummy return a empty implement version of HTTP template
-func NewHTTPTemplateDummy() *HTTPTemplate {
- return &HTTPTemplate{
- Engine: texttemplate.NewDummyTemplate(),
- filterExecFuncs: map[string]filterDictFuncs{},
- }
-}
-
 func readBody(body io.Reader, maxBodySize int64) (*bytes.Buffer, error) {
  buff := bytes.NewBuffer(nil)
  if body == nil {

pkg/filter/circuitbreaker/circuitbreaker.go

@@ -28,6 +28,7 @@ import (
  "github.com/megaease/easegress/pkg/logger"
  "github.com/megaease/easegress/pkg/object/httppipeline"
  libcb "github.com/megaease/easegress/pkg/util/circuitbreaker"
+ "github.com/megaease/easegress/pkg/util/fasttime"
  "github.com/megaease/easegress/pkg/util/urlrule"
 )
 
@@ -295,7 +296,7 @@ func (cb *CircuitBreaker) handle(ctx context.HTTPContext, u *URLRule) string {
  return ctx.CallNextHandler(resultShortCircuited)
  }
 
- start := time.Now()
+ start := fasttime.Now()
  defer func() {
  if e := recover(); e != nil {
  d := time.Since(start)