Added performance monitoring

src/perf/perf.go

@@ -0,0 +1,130 @@
+package perf
+
+import (
+	"context"
+	"time"
+)
+
+type RequestPerf struct {
+	Route  string
+	Start  time.Time
+	End    time.Time
+	Blocks []PerfBlock
+}
+
+func MakeNewRequestPerf(route string) *RequestPerf {
+	return &RequestPerf{
+		Start: time.Now(),
+		Route: route,
+	}
+}
+
+func (rp *RequestPerf) EndRequest() {
+	for rp.EndBlock() {
+	}
+	rp.End = time.Now()
+}
+
+func (rp *RequestPerf) Checkpoint(category, description string) {
+	now := time.Now()
+	checkpoint := PerfBlock{
+		Start:       now,
+		End:         now,
+		Category:    category,
+		Description: description,
+	}
+	rp.Blocks = append(rp.Blocks, checkpoint)
+}
+
+func (rp *RequestPerf) StartBlock(category, description string) {
+	now := time.Now()
+	checkpoint := PerfBlock{
+		Start:       now,
+		End:         time.Time{},
+		Category:    category,
+		Description: description,
+	}
+	rp.Blocks = append(rp.Blocks, checkpoint)
+}
+
+func (rp *RequestPerf) EndBlock() bool {
+	for i := len(rp.Blocks) - 1; i >= 0; i -= 1 {
+		if rp.Blocks[i].End.Equal(time.Time{}) {
+			rp.Blocks[i].End = time.Now()
+			return true
+		}
+	}
+	return false
+}
+
+func (rp *RequestPerf) MsFromStart(block *PerfBlock) float64 {
+	return float64(block.Start.Sub(rp.Start).Nanoseconds()) / 1000 / 1000
+}
+
+type PerfBlock struct {
+	Start       time.Time
+	End         time.Time
+	Category    string
+	Description string
+}
+
+func (pb *PerfBlock) Duration() time.Duration {
+	return pb.End.Sub(pb.Start)
+}
+
+func (pb *PerfBlock) DurationMs() float64 {
+	return float64(pb.Duration().Nanoseconds()) / 1000 / 1000
+}
+
+type PerfStorage struct {
+	AllRequests []RequestPerf
+}
+
+type PerfCollector struct {
+	In          chan<- RequestPerf
+	Done        <-chan struct{}
+	RequestCopy chan<- (chan<- PerfStorage)
+}
+
+func RunPerfCollector(ctx context.Context) *PerfCollector {
+	in := make(chan RequestPerf)
+	done := make(chan struct{})
+	requestCopy := make(chan (chan<- PerfStorage))
+
+	var storage PerfStorage
+	// TODO(asaf): Load history from file
+
+	go func() {
+		defer close(done)
+
+		for {
+			select {
+			case perf := <-in:
+				storage.AllRequests = append(storage.AllRequests, perf)
+				// TODO(asaf): Write to file
+			case resultChan := <-requestCopy:
+				resultChan <- storage
+			case <-ctx.Done():
+				return
+			}
+		}
+	}()
+
+	perfCollector := PerfCollector{
+		In:          in,
+		Done:        done,
+		RequestCopy: requestCopy,
+	}
+	return &perfCollector
+}
+
+func (perfCollector *PerfCollector) SubmitRun(run *RequestPerf) {
+	perfCollector.In <- *run
+}
+
+func (perfCollector *PerfCollector) GetPerfCopy() *PerfStorage {
+	resultChan := make(chan PerfStorage)
+	perfCollector.RequestCopy <- resultChan
+	perfStorageCopy := <-resultChan
+	return &perfStorageCopy
+}

src/website/feed.go

@@ -23,6 +23,7 @@ type FeedData struct {
 func Feed(c *RequestContext) ResponseData {
 	const postsPerPage = 30
 
+	c.Perf.StartBlock("SQL", "Count posts")
 	numPosts, err := db.QueryInt(c.Context(), c.Conn,
 		`
 		SELECT COUNT(*)
@@ -38,6 +39,7 @@ func Feed(c *RequestContext) ResponseData {
 		models.CatTypeWiki,
 		models.CatTypeLibraryResource,
 	) // TODO(inarray)
+	c.Perf.EndBlock()
 	if err != nil {
 		return ErrorResponse(http.StatusInternalServerError, oops.New(err, "failed to get count of feed posts"))
 	}
@@ -71,6 +73,7 @@ func Feed(c *RequestContext) ResponseData {
 		currentUserId = &c.CurrentUser.ID
 	}
 
+	c.Perf.StartBlock("SQL", "Fetch posts")
 	type feedPostQuery struct {
 		Post               models.Post     `db:"post"`
 		Thread             models.Thread   `db:"thread"`
@@ -112,6 +115,7 @@ func Feed(c *RequestContext) ResponseData {
 		postsPerPage,
 		howManyPostsToSkip,
 	) // TODO(inarray)
+	c.Perf.EndBlock()
 	if err != nil {
 		return ErrorResponse(http.StatusInternalServerError, oops.New(err, "failed to fetch feed posts"))
 	}
@@ -163,7 +167,7 @@ func Feed(c *RequestContext) ResponseData {
 
 		Posts:      postItems,
 		Pagination: pagination,
-	})
+	}, c.Perf)
 
 	return res
 }

src/website/landing.go

@@ -1,6 +1,7 @@
 package website
 
 import (
+	"fmt"
 	"html/template"
 	"net/http"
 	"time"
@@ -38,6 +39,7 @@ func Index(c *RequestContext) ResponseData {
 	const maxPosts = 5
 	const numProjectsToGet = 7
 
+	c.Perf.StartBlock("SQL", "Fetch projects")
 	iterProjects, err := db.Query(c.Context(), c.Conn, models.Project{},
 		`
 		SELECT $columns
@@ -59,6 +61,7 @@ func Index(c *RequestContext) ResponseData {
 	var pageProjects []LandingPageProject
 
 	allProjects := iterProjects.ToSlice()
+	c.Perf.EndBlock()
 	c.Logger.Info().Interface("allProjects", allProjects).Msg("all the projects")
 
 	var currentUserId *int
@@ -66,9 +69,11 @@ func Index(c *RequestContext) ResponseData {
 		currentUserId = &c.CurrentUser.ID
 	}
 
+	c.Perf.StartBlock("LANDING", "Process projects")
 	for _, projRow := range allProjects {
 		proj := projRow.(*models.Project)
 
+		c.Perf.StartBlock("SQL", fmt.Sprintf("Fetch posts for %s", *proj.Name))
 		type projectPostQuery struct {
 			Post               models.Post     `db:"post"`
 			Thread             models.Thread   `db:"thread"`
@@ -106,6 +111,7 @@ func Index(c *RequestContext) ResponseData {
 			models.CatTypeBlog, models.CatTypeForum, models.CatTypeWiki, models.CatTypeLibraryResource,
 			maxPosts,
 		)
+		c.Perf.EndBlock()
 		if err != nil {
 			c.Logger.Error().Err(err).Msg("failed to fetch project posts")
 			continue
@@ -136,6 +142,7 @@ func Index(c *RequestContext) ResponseData {
 					Content string `db:"ver.text_parsed"`
 				}
 
+				c.Perf.StartBlock("SQL", "Fetch featured post content")
 				contentResult, err := db.QueryOne(c.Context(), c.Conn, featuredContentResult{}, `
 					SELECT $columns
 					FROM
@@ -147,6 +154,7 @@ func Index(c *RequestContext) ResponseData {
 				if err != nil {
 					panic(err)
 				}
+				c.Perf.EndBlock()
 				content := contentResult.(*featuredContentResult).Content
 
 				landingPageProject.FeaturedPost = &LandingPageFeaturedPost{
@@ -176,7 +184,9 @@ func Index(c *RequestContext) ResponseData {
 			break
 		}
 	}
+	c.Perf.EndBlock()
 
+	c.Perf.StartBlock("SQL", "Get news")
 	type newsThreadQuery struct {
 		Thread models.Thread `db:"thread"`
 	}
@@ -196,6 +206,7 @@ func Index(c *RequestContext) ResponseData {
 	if err != nil {
 		return ErrorResponse(http.StatusInternalServerError, oops.New(err, "failed to fetch latest news post"))
 	}
+	c.Perf.EndBlock()
 	newsThread := newsThreadRow.(*newsThreadQuery)
 	_ = newsThread // TODO: NO
 
@@ -275,7 +286,7 @@ func Index(c *RequestContext) ResponseData {
 			Content: template.HTML(newsPostResult.PostVersion.TextParsed),
 		},
 		PostColumns: cols,
-	})
+	}, c.Perf)
 	if err != nil {
 		panic(err)
 	}

src/website/requesthandling.go

@@ -12,6 +12,7 @@ import (
 
 	"git.handmade.network/hmn/hmn/src/logging"
 	"git.handmade.network/hmn/hmn/src/models"
+	"git.handmade.network/hmn/hmn/src/perf"
 	"git.handmade.network/hmn/hmn/src/templates"
 	"github.com/jackc/pgx/v4/pgxpool"
 	"github.com/julienschmidt/httprouter"
@@ -37,7 +38,7 @@ type HMNBeforeHandler func(c *RequestContext) (ok bool, res ResponseData)
 type HMNAfterHandler func(c *RequestContext, res ResponseData) ResponseData
 
 func (h HMNHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
-	c := NewRequestContext(rw, req, nil)
+	c := NewRequestContext(rw, req, nil, "")
 	doRequest(rw, c, h)
 }
 
@@ -47,15 +48,17 @@ type RequestContext struct {
 	PathParams httprouter.Params
 
 	Conn           *pgxpool.Pool
+	Perf           *perf.RequestPerf
 	CurrentProject *models.Project
 	CurrentUser    *models.User
 }
 
-func NewRequestContext(rw http.ResponseWriter, req *http.Request, pathParams httprouter.Params) *RequestContext {
+func NewRequestContext(rw http.ResponseWriter, req *http.Request, pathParams httprouter.Params, route string) *RequestContext {
 	return &RequestContext{
 		Logger:     logging.GlobalLogger(),
 		Req:        req,
 		PathParams: pathParams,
+		Perf:       perf.MakeNewRequestPerf(route),
 	}
 }
 
@@ -161,7 +164,11 @@ func (rd *ResponseData) SetCookie(cookie *http.Cookie) {
 	rd.Headers().Add("Set-Cookie", cookie.String())
 }
 
-func (rd *ResponseData) WriteTemplate(name string, data interface{}) error {
+func (rd *ResponseData) WriteTemplate(name string, data interface{}, rp *perf.RequestPerf) error {
+	if rp != nil {
+		rp.StartBlock("TEMPLATE", name)
+		defer rp.EndBlock()
+	}
 	return templates.Templates[name].Execute(rd, data)
 }
 
@@ -196,7 +203,7 @@ func (b RouteBuilder) ChainHandlers(h HMNHandler) HMNHandler {
 func (b *RouteBuilder) Handle(method, route string, handler HMNHandler) {
 	h := b.ChainHandlers(handler)
 	b.Router.Handle(method, route, func(rw http.ResponseWriter, req *http.Request, p httprouter.Params) {
-		c := NewRequestContext(rw, req, p)
+		c := NewRequestContext(rw, req, p, route)
 		doRequest(rw, c, h)
 	})
 }

src/website/routes.go

@@ -4,20 +4,23 @@ import (
 	"bytes"
 	"context"
 	"errors"
+	"fmt"
 	"net/http"
 	"strings"
+	"time"
 
 	"git.handmade.network/hmn/hmn/src/auth"
 	"git.handmade.network/hmn/hmn/src/db"
 	"git.handmade.network/hmn/hmn/src/logging"
 	"git.handmade.network/hmn/hmn/src/models"
 	"git.handmade.network/hmn/hmn/src/oops"
+	"git.handmade.network/hmn/hmn/src/perf"
 	"git.handmade.network/hmn/hmn/src/templates"
 	"github.com/jackc/pgx/v4/pgxpool"
 	"github.com/julienschmidt/httprouter"
 )
 
-func NewWebsiteRoutes(conn *pgxpool.Pool) http.Handler {
+func NewWebsiteRoutes(conn *pgxpool.Pool, perfCollector *perf.PerfCollector) http.Handler {
 	router := httprouter.New()
 	routes := RouteBuilder{
 		Router: router,
@@ -28,7 +31,25 @@ func NewWebsiteRoutes(conn *pgxpool.Pool) http.Handler {
 			},
 			// TODO: Add a timeout? We don't want routes hanging forever
 		},
-		AfterHandlers: []HMNAfterHandler{ErrorLoggingHandler},
+		AfterHandlers: []HMNAfterHandler{
+			ErrorLoggingHandler,
+			func(c *RequestContext, res ResponseData) ResponseData {
+				// Do perf printout
+				c.Perf.EndRequest()
+				log := logging.Info()
+				blockStack := make([]time.Time, 0)
+				for _, block := range c.Perf.Blocks {
+					for len(blockStack) > 0 && block.End.After(blockStack[len(blockStack)-1]) {
+						blockStack = blockStack[:len(blockStack)-1]
+					}
+					log.Str(fmt.Sprintf("At %9.2fms", c.Perf.MsFromStart(&block)), fmt.Sprintf("%*.s[%s] %s (%.4fms)", len(blockStack)*2, "", block.Category, block.Description, block.DurationMs()))
+					blockStack = append(blockStack, block.End)
+				}
+				log.Msg(fmt.Sprintf("Served %s in %.4fms", c.Perf.Route, float64(c.Perf.End.Sub(c.Perf.Start).Nanoseconds())/1000/1000))
+				perfCollector.SubmitRun(c.Perf)
+				return res
+			},
+		},
 	}
 
 	routes.POST("/login", Login)
@@ -136,7 +157,7 @@ func ProjectCSS(c *RequestContext) ResponseData {
 
 	var res ResponseData
 	res.Headers().Add("Content-Type", "text/css")
-	err := res.WriteTemplate("project.css", templateData)
+	err := res.WriteTemplate("project.css", templateData, c.Perf)
 	if err != nil {
 		return ErrorResponse(http.StatusInternalServerError, oops.New(err, "failed to generate project CSS"))
 	}
@@ -160,6 +181,8 @@ func ErrorLoggingHandler(c *RequestContext, res ResponseData) ResponseData {
 }
 
 func CommonWebsiteDataWrapper(c *RequestContext) (bool, ResponseData) {
+	c.Perf.StartBlock("MIDDLEWARE", "Load common website data")
+	defer c.Perf.EndBlock()
 	// get project
 	{
 		slug := ""
@@ -176,6 +199,7 @@ func CommonWebsiteDataWrapper(c *RequestContext) (bool, ResponseData) {
 		c.CurrentProject = dbProject
 	}
 
+	{
 		sessionCookie, err := c.Req.Cookie(auth.SessionCookieName)
 		if err == nil {
 			user, err := getCurrentUser(c, sessionCookie.Value)
@@ -186,6 +210,7 @@ func CommonWebsiteDataWrapper(c *RequestContext) (bool, ResponseData) {
 			c.CurrentUser = user
 		}
 		// http.ErrNoCookie is the only error Cookie ever returns, so no further handling to do here.
+	}
 
 	return true, ResponseData{}
 }

src/website/website.go

@@ -12,6 +12,7 @@ import (
 	"git.handmade.network/hmn/hmn/src/config"
 	"git.handmade.network/hmn/hmn/src/db"
 	"git.handmade.network/hmn/hmn/src/logging"
+	"git.handmade.network/hmn/hmn/src/perf"
 	"git.handmade.network/hmn/hmn/src/templates"
 	"github.com/spf13/cobra"
 )
@@ -25,16 +26,19 @@ var WebsiteCommand = &cobra.Command{
 
 		logging.Info().Msg("Hello, HMN!")
 
+		backgroundJobContext, cancelBackgroundJobs := context.WithCancel(context.Background())
+
 		conn := db.NewConnPool(config.Config.Postgres.MinConn, config.Config.Postgres.MaxConn)
+		perfCollector := perf.RunPerfCollector(backgroundJobContext)
 
 		server := http.Server{
 			Addr:    config.Config.Addr,
-			Handler: NewWebsiteRoutes(conn),
+			Handler: NewWebsiteRoutes(conn, perfCollector),
 		}
 
-		backgroundJobContext, cancelBackgroundJobs := context.WithCancel(context.Background())
 		backgroundJobsDone := zipJobs(
 			auth.PeriodicallyDeleteExpiredSessions(backgroundJobContext, conn),
+			perfCollector.Done,
 		)
 
 		signals := make(chan os.Signal, 1)