Template rendering performance issue has been fixed (#60)

.golangci.yml

@@ -42,7 +42,9 @@ linters: # All available linters list: <https://golangci-lint.run/usage/linters/
   disable-all: true
   enable:
     - asciicheck # Simple linter to check that your code does not contain non-ASCII identifiers
+    - bidichk # Checks for dangerous unicode character sequences
     - bodyclose # Checks whether HTTP response body is closed successfully
+    - contextcheck # check the function whether use a non-inherited context
     - deadcode # Finds unused code
     - depguard # Go linter that checks if package imports are in a list of acceptable packages
     - dogsled # Checks assignments with too many blank identifiers (e.g. x, _, _, _, := f())

CHANGELOG.md

@@ -14,6 +14,11 @@ The format is based on [Keep a Changelog][keepachangelog] and this project adher
 
 - `Host` and `X-Forwarded-For` Header to error pages [#61]
 
+### Fixed
+
+- Performance issue, that affects template rendering. Now templates are cached in memory (for 2 seconds), and it has improved performance by more than 200% [#60]
+
+[#60]:https://github.com/tarampampam/error-pages/pull/60
 [#61]:https://github.com/tarampampam/error-pages/pull/61
 
 ## v2.4.0

README.md

@@ -80,25 +80,24 @@ $ ulimit -aH | grep file
 -n: file descriptors                1048576
 -x: file locks                      unlimited
 
-$ wrk --version | head -n 1
+$ docker run --rm -p "8080:8080/tcp" -e "SHOW_DETAILS=true" error-pages:local # in separate terminal
-wrk 4.2.0 [epoll] Copyright (C) 2012 Will Glozer
 
-$ wrk -t12 -c400 -d30s http://127.0.0.1:8080/500.html
+$ wrk --timeout 1s -t12 -c400 -d30s -s ./test/wrk/request.lua http://127.0.0.1:8080/
-Running 30s test @ http://127.0.0.1:8080/500.html
+Running 30s test @ http://127.0.0.1:8080/
   12 threads and 400 connections
   Thread Stats   Avg      Stdev     Max   +/- Stdev
-    Latency    50.06ms   61.15ms 655.79ms   85.54%
+    Latency    10.84ms    7.89ms 135.91ms   79.36%
-    Req/Sec     1.07k   363.14     2.40k    69.24%
+    Req/Sec     3.23k   785.11     6.30k    70.04%
-  383014 requests in 30.08s, 2.14GB read
+  1160567 requests in 30.10s, 4.12GB read
-Requests/sec:  12731.07
+Requests/sec:  38552.04
-Transfer/sec:     72.79MB
+Transfer/sec:    140.23MB
 ```
 
 <details>
   <summary>FS & memory usage stats during the test</summary>
 
   <p align="center">
-    <img src="https://hsto.org/webt/dy/2e/_8/dy2e_8xkefxre7z5w7xcorjldmm.png" alt="" />
+    <img src="https://hsto.org/webt/ts/w-/lz/tsw-lznvru0ngjneiimkwq7ysyc.png" alt="" />
   </p>
 </details>
 

internal/cli/build/command.go

@@ -71,7 +71,8 @@ func run(log *zap.Logger, cfg *config.Config, outDirectoryPath string, generateI
 		return errors.Wrap(err, "cannot prepare output directory")
 	}
 
-	history := newBuildingHistory()
+	history, renderer := newBuildingHistory(), tpl.NewTemplateRenderer()
+	defer func() { _ = renderer.Close() }()
 
 	for _, template := range cfg.Templates {
 		log.Debug("template processing", zap.String("name", template.Name()))
@@ -86,7 +87,7 @@ func run(log *zap.Logger, cfg *config.Config, outDirectoryPath string, generateI
 				filePath = path.Join(outDirectoryPath, template.Name(), fileName)
 			)
 
-			content, renderingErr := tpl.Render(template.Content(), tpl.Properties{
+			content, renderingErr := renderer.Render(template.Content(), tpl.Properties{
 				Code:               page.Code(),
 				Message:            page.Message(),
 				Description:        page.Description(),

internal/http/core/errorpage.go

@@ -13,10 +13,15 @@ type templatePicker interface {
 	Pick() string
 }
 
+type renderer interface {
+	Render(content []byte, props tpl.Properties) ([]byte, error)
+}
+
 func RespondWithErrorPage( //nolint:funlen
 	ctx *fasthttp.RequestCtx,
 	cfg *config.Config,
 	p templatePicker,
+	rdr renderer,
 	pageCode string,
 	httpCode int,
 	showRequestDetails bool,
@@ -64,7 +69,7 @@ func RespondWithErrorPage( //nolint:funlen
 		{
 			SetClientFormat(ctx, JSONContentType)
 
-			if content, err := tpl.Render(json.Content(), props); err == nil {
+			if content, err := rdr.Render(json.Content(), props); err == nil {
 				ctx.SetStatusCode(httpCode)
 				_, _ = ctx.Write(content)
 			} else {
@@ -77,7 +82,7 @@ func RespondWithErrorPage( //nolint:funlen
 		{
 			SetClientFormat(ctx, XMLContentType)
 
-			if content, err := tpl.Render(xml.Content(), props); err == nil {
+			if content, err := rdr.Render(xml.Content(), props); err == nil {
 				ctx.SetStatusCode(httpCode)
 				_, _ = ctx.Write(content)
 			} else {
@@ -93,7 +98,7 @@ func RespondWithErrorPage( //nolint:funlen
 			var templateName = p.Pick()
 
 			if template, exists := cfg.Template(templateName); exists {
-				if content, err := tpl.Render(template.Content(), props); err == nil {
+				if content, err := rdr.Render(template.Content(), props); err == nil {
 					ctx.SetStatusCode(httpCode)
 					_, _ = ctx.Write(content)
 				} else {

internal/http/handlers/errorpage/handler.go

@@ -3,21 +3,28 @@ package errorpage
 import (
 	"github.com/tarampampam/error-pages/internal/config"
 	"github.com/tarampampam/error-pages/internal/http/core"
+	"github.com/tarampampam/error-pages/internal/tpl"
 	"github.com/valyala/fasthttp"
 )
 
-type templatePicker interface {
+type (
+	templatePicker interface {
 		// Pick the template name for responding.
 		Pick() string
-}
+	}
+
+	renderer interface {
+		Render(content []byte, props tpl.Properties) ([]byte, error)
+	}
+)
 
 // NewHandler creates handler for error pages serving.
-func NewHandler(cfg *config.Config, p templatePicker, showRequestDetails bool) fasthttp.RequestHandler {
+func NewHandler(cfg *config.Config, p templatePicker, rdr renderer, showRequestDetails bool) fasthttp.RequestHandler {
 	return func(ctx *fasthttp.RequestCtx) {
 		core.SetClientFormat(ctx, core.PlainTextContentType) // default content type
 
 		if code, ok := ctx.UserValue("code").(string); ok {
-			core.RespondWithErrorPage(ctx, cfg, p, code, fasthttp.StatusOK, showRequestDetails)
+			core.RespondWithErrorPage(ctx, cfg, p, rdr, code, fasthttp.StatusOK, showRequestDetails)
 		} else { // will never occur
 			ctx.SetStatusCode(fasthttp.StatusInternalServerError)
 			_, _ = ctx.WriteString("cannot extract requested code from the request")

internal/http/handlers/index/handler.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/tarampampam/error-pages/internal/config"
 	"github.com/tarampampam/error-pages/internal/http/core"
+	"github.com/tarampampam/error-pages/internal/tpl"
 	"github.com/valyala/fasthttp"
 )
 
@@ -13,12 +14,17 @@ type (
 		// Pick the template name for responding.
 		Pick() string
 	}
+
+	renderer interface {
+		Render(content []byte, props tpl.Properties) ([]byte, error)
+	}
 )
 
 // NewHandler creates handler for the index page serving.
 func NewHandler(
 	cfg *config.Config,
 	p templatePicker,
+	rdr renderer,
 	defaultPageCode string,
 	defaultHTTPCode uint16,
 	showRequestDetails bool,
@@ -30,7 +36,7 @@ func NewHandler(
 			pageCode, httpCode = strconv.Itoa(returnCode), returnCode
 		}
 
-		core.RespondWithErrorPage(ctx, cfg, p, pageCode, httpCode, showRequestDetails)
+		core.RespondWithErrorPage(ctx, cfg, p, rdr, pageCode, httpCode, showRequestDetails)
 	}
 }
 

internal/http/server.go

@@ -4,6 +4,8 @@ import (
 	"strconv"
 	"time"
 
+	"github.com/tarampampam/error-pages/internal/tpl"
+
 	"github.com/fasthttp/router"
 	"github.com/tarampampam/error-pages/internal/checkers"
 	"github.com/tarampampam/error-pages/internal/config"
@@ -24,6 +26,7 @@ type Server struct {
 	log    *zap.Logger
 	fast   *fasthttp.Server
 	router *router.Router
+	rdr    *tpl.TemplateRenderer
 }
 
 const (
@@ -33,6 +36,8 @@ const (
 )
 
 func NewServer(log *zap.Logger) Server {
+	rdr := tpl.NewTemplateRenderer()
+
 	return Server{
 		// fasthttp docs: <https://github.com/valyala/fasthttp>
 		fast: &fasthttp.Server{
@@ -46,6 +51,7 @@ func NewServer(log *zap.Logger) Server {
 		},
 		router: router.New(),
 		log:    log,
+		rdr:    rdr,
 	}
 }
 
@@ -76,8 +82,8 @@ func (s *Server) Register(
 
 	s.fast.Handler = common.DurationMetrics(common.LogRequest(s.router.Handler, s.log), &m)
 
-	s.router.GET("/", indexHandler.NewHandler(cfg, templatePicker, defaultPageCode, defaultHTTPCode, showDetails))
+	s.router.GET("/", indexHandler.NewHandler(cfg, templatePicker, s.rdr, defaultPageCode, defaultHTTPCode, showDetails)) //nolint:lll
-	s.router.GET("/{code}.html", errorpageHandler.NewHandler(cfg, templatePicker, showDetails))
+	s.router.GET("/{code}.html", errorpageHandler.NewHandler(cfg, templatePicker, s.rdr, showDetails))
 	s.router.GET("/version", versionHandler.NewHandler(version.Version()))
 
 	liveHandler := healthzHandler.NewHandler(checkers.NewLiveChecker())
@@ -92,4 +98,12 @@ func (s *Server) Register(
 }
 
 // Stop server.
-func (s *Server) Stop() error { return s.fast.Shutdown() }
+func (s *Server) Stop() error {
+	if err := s.rdr.Close(); err != nil {
+		defer func() { _ = s.fast.Shutdown() }()
+
+		return err
+	}
+
+	return s.fast.Shutdown()
+}

internal/tpl/hasher.go

@@ -0,0 +1,25 @@
+package tpl
+
+import (
+	"bytes"
+	"crypto/md5" //nolint:gosec
+	"encoding/gob"
+)
+
+const hashLength = 16 // md5 hash length
+
+type Hash [hashLength]byte
+
+func HashStruct(s interface{}) (Hash, error) {
+	var b bytes.Buffer
+
+	if err := gob.NewEncoder(&b).Encode(s); err != nil {
+		return Hash{}, err
+	}
+
+	return md5.Sum(b.Bytes()), nil //nolint:gosec
+}
+
+func HashBytes(b []byte) Hash {
+	return md5.Sum(b) //nolint:gosec
+}

internal/tpl/hasher_test.go

@@ -0,0 +1,35 @@
+package tpl_test
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/tarampampam/error-pages/internal/tpl"
+)
+
+func TestHashBytes(t *testing.T) {
+	assert.NotEqual(t, tpl.HashBytes([]byte{1}), tpl.HashBytes([]byte{2}))
+}
+
+func TestHashStruct(t *testing.T) {
+	type s struct {
+		S string
+		I int
+		B bool
+	}
+
+	h1, err1 := tpl.HashStruct(s{S: "foo", I: 1, B: false})
+	assert.NoError(t, err1)
+
+	h2, err2 := tpl.HashStruct(s{S: "bar", I: 2, B: true})
+	assert.NoError(t, err2)
+
+	assert.NotEqual(t, h1, h2)
+
+	type p struct { // no exported fields
+		any string
+	}
+
+	_, err := tpl.HashStruct(p{any: "foo"})
+	assert.Error(t, err)
+}

internal/tpl/properties.go

@@ -1,6 +1,8 @@
 package tpl
 
-import "reflect"
+import (
+	"reflect"
+)
 
 type Properties struct { // only string properties with a "token" tag, please
 	Code               string `token:"code"`
@@ -33,3 +35,5 @@ func (p *Properties) Replaces() map[string]string {
 
 	return replaces
 }
+
+func (p *Properties) Hash() (Hash, error) { return HashStruct(p) }

internal/tpl/render.go

@@ -5,13 +5,17 @@ import (
 	"encoding/json"
 	"os"
 	"strconv"
+	"sync"
 	"text/template"
 	"time"
 
+	"github.com/pkg/errors"
+
 	"github.com/tarampampam/error-pages/internal/version"
 )
 
-var tplFnMap = template.FuncMap{ //nolint:gochecknoglobals // these functions can be used in templates
+// These functions are always allowed in the templates.
+var tplFnMap = template.FuncMap{ //nolint:gochecknoglobals
 	"now":      time.Now,
 	"hostname": os.Hostname,
 	"json":     func(v interface{}) string { b, _ := json.Marshal(v); return string(b) }, //nolint:nlreturn
@@ -29,11 +33,113 @@ var tplFnMap = template.FuncMap{ //nolint:gochecknoglobals // these functions ca
 	},
 }
 
-func Render(content []byte, props Properties) ([]byte, error) {
+var ErrClosed = errors.New("closed")
+
+type TemplateRenderer struct {
+	cacheMu sync.RWMutex
+	cache   map[cacheEntryHash]cacheItem // map key is a unique hash
+
+	cacheCleanupInterval time.Duration
+	cacheItemLifetime    time.Duration
+
+	close    chan struct{}
+	closedMu sync.RWMutex
+	closed   bool
+}
+
+type (
+	cacheEntryHash = [hashLength * 2]byte // two md5 hashes
+	cacheItem      struct {
+		data          []byte
+		expiresAtNano int64
+	}
+)
+
+const (
+	cacheCleanupInterval = time.Second
+	cacheItemLifetime    = time.Second * 2
+)
+
+// NewTemplateRenderer returns new template renderer. Don't forget to call Close() function!
+func NewTemplateRenderer() *TemplateRenderer {
+	tr := &TemplateRenderer{
+		cache:                make(map[cacheEntryHash]cacheItem),
+		cacheCleanupInterval: cacheCleanupInterval,
+		cacheItemLifetime:    cacheItemLifetime,
+		close:                make(chan struct{}, 1),
+	}
+
+	go tr.cleanup()
+
+	return tr
+}
+
+func (tr *TemplateRenderer) cleanup() {
+	defer close(tr.close)
+
+	timer := time.NewTimer(tr.cacheCleanupInterval)
+	defer timer.Stop()
+
+	for {
+		select {
+		case <-tr.close:
+			tr.cacheMu.Lock()
+			for hash := range tr.cache {
+				delete(tr.cache, hash)
+			}
+			tr.cacheMu.Unlock()
+
+			return
+
+		case <-timer.C:
+			tr.cacheMu.Lock()
+			var now = time.Now().UnixNano()
+
+			for hash, item := range tr.cache {
+				if now > item.expiresAtNano {
+					delete(tr.cache, hash)
+				}
+			}
+			tr.cacheMu.Unlock()
+
+			timer.Reset(tr.cacheCleanupInterval)
+		}
+	}
+}
+
+func (tr *TemplateRenderer) Render(content []byte, props Properties) ([]byte, error) { //nolint:funlen
+	if tr.isClosed() {
+		return nil, ErrClosed
+	}
+
 	if len(content) == 0 {
 		return content, nil
 	}
 
+	var (
+		cacheKey     cacheEntryHash
+		cacheKeyInit bool
+	)
+
+	if propsHash, err := props.Hash(); err == nil {
+		cacheKeyInit, cacheKey = true, tr.mixHashes(propsHash, HashBytes(content))
+
+		tr.cacheMu.RLock()
+		item, hit := tr.cache[cacheKey]
+		tr.cacheMu.RUnlock()
+
+		if hit {
+			// cache item has been expired?
+			if time.Now().UnixNano() > item.expiresAtNano {
+				tr.cacheMu.Lock()
+				delete(tr.cache, cacheKey)
+				tr.cacheMu.Unlock()
+			} else {
+				return item.data, nil
+			}
+		}
+	}
+
 	var funcMap = template.FuncMap{
 		"show_details": func() bool { return props.ShowRequestDetails },
 		"hide_details": func() bool { return !props.ShowRequestDetails },
@@ -62,5 +168,50 @@ func Render(content []byte, props Properties) ([]byte, error) {
 		return nil, err
 	}
 
-	return buf.Bytes(), nil
+	b := buf.Bytes()
+
+	if cacheKeyInit {
+		tr.cacheMu.Lock()
+		tr.cache[cacheKey] = cacheItem{
+			data:          b,
+			expiresAtNano: time.Now().UnixNano() + tr.cacheItemLifetime.Nanoseconds(),
+		}
+		tr.cacheMu.Unlock()
+	}
+
+	return b, nil
+}
+
+func (tr *TemplateRenderer) isClosed() (closed bool) {
+	tr.closedMu.RLock()
+	closed = tr.closed
+	tr.closedMu.RUnlock()
+
+	return
+}
+
+func (tr *TemplateRenderer) Close() error {
+	if tr.isClosed() {
+		return ErrClosed
+	}
+
+	tr.closedMu.Lock()
+	tr.closed = true
+	tr.closedMu.Unlock()
+
+	tr.close <- struct{}{}
+
+	return nil
+}
+
+func (tr *TemplateRenderer) mixHashes(a, b Hash) (result cacheEntryHash) {
+	for i := 0; i < len(a); i++ {
+		result[i] = a[i]
+	}
+
+	for i := 0; i < len(b); i++ {
+		result[i+len(a)] = b[i]
+	}
+
+	return
 }

internal/tpl/render_test.go

@@ -1,6 +1,9 @@
 package tpl_test
 
 import (
+	"math/rand"
+	"strconv"
+	"sync"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -8,6 +11,9 @@ import (
 )
 
 func Test_Render(t *testing.T) {
+	renderer := tpl.NewTemplateRenderer()
+	defer func() { _ = renderer.Close() }()
+
 	for name, tt := range map[string]struct {
 		giveContent string
 		giveProps   tpl.Properties
@@ -52,7 +58,7 @@ func Test_Render(t *testing.T) {
 		},
 	} {
 		t.Run(name, func(t *testing.T) {
-			content, err := tpl.Render([]byte(tt.giveContent), tt.giveProps)
+			content, err := renderer.Render([]byte(tt.giveContent), tt.giveProps)
 
 			if tt.wantError == true {
 				assert.Error(t, err)
@@ -64,11 +70,48 @@ func Test_Render(t *testing.T) {
 	}
 }
 
+func TestTemplateRenderer_Render_Concurrent(t *testing.T) {
+	renderer := tpl.NewTemplateRenderer()
+
+	var wg sync.WaitGroup
+
+	for i := 0; i < 100; i++ {
+		wg.Add(1)
+
+		go func() {
+			defer wg.Done()
+
+			props := tpl.Properties{
+				Code:        strconv.Itoa(rand.Intn(599-300+1) + 300), //nolint:gosec
+				Message:     "Not found",
+				Description: "Blah",
+			}
+
+			content, err := renderer.Render([]byte("{{code}}: {{ message }} {{description}}"), props)
+
+			assert.NoError(t, err)
+			assert.NotEmpty(t, content)
+		}()
+	}
+
+	wg.Wait()
+
+	assert.NoError(t, renderer.Close())
+	assert.EqualError(t, renderer.Close(), tpl.ErrClosed.Error())
+
+	content, err := renderer.Render([]byte{}, tpl.Properties{})
+	assert.Nil(t, content)
+	assert.EqualError(t, err, tpl.ErrClosed.Error())
+}
+
 func BenchmarkRenderHTML(b *testing.B) {
 	b.ReportAllocs()
 
+	renderer := tpl.NewTemplateRenderer()
+	defer func() { _ = renderer.Close() }()
+
 	for i := 0; i < b.N; i++ {
-		_, _ = tpl.Render(
+		_, _ = renderer.Render(
 			[]byte("{{code}}: {{ message }} {{description}}"),
 			tpl.Properties{Code: "404", Message: "Not found", Description: "Blah"},
 		)

test/wrk/request.lua

@@ -0,0 +1,9 @@
+local formats = { 'application/json', 'application/xml', 'text/html', 'text/plain' }
+
+request = function()
+    wrk.headers["X-Namespace"] = "NAMESPACE_" .. tostring(math.random(0, 99999999))
+    wrk.headers["X-Request-ID"] = "REQ_ID_" .. tostring(math.random(0, 99999999))
+    wrk.headers["Content-Type"] = formats[ math.random( 0, #formats - 1 ) ]
+
+    return wrk.format("GET", "/500.html?rnd=" .. tostring(math.random(0, 99999999)), nil, nil)
+end