From 24c69b81575c0ec1573b092cb8516c2800bfeee6 Mon Sep 17 00:00:00 2001 From: Asaf Gartner Date: Mon, 26 Apr 2021 09:56:49 +0300 Subject: [PATCH] Added performance monitoring --- src/perf/perf.go | 130 +++++++++++++++++++++++++++++++++ src/website/feed.go | 6 +- src/website/landing.go | 13 +++- src/website/requesthandling.go | 15 +++- src/website/routes.go | 47 +++++++++--- src/website/website.go | 8 +- 6 files changed, 200 insertions(+), 19 deletions(-) create mode 100644 src/perf/perf.go diff --git a/src/perf/perf.go b/src/perf/perf.go new file mode 100644 index 0000000..e1eeaac --- /dev/null +++ b/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 +} diff --git a/src/website/feed.go b/src/website/feed.go index 7d9600a..4c92cbe 100644 --- a/src/website/feed.go +++ b/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 } diff --git a/src/website/landing.go b/src/website/landing.go index 6c13c09..034df5c 100644 --- a/src/website/landing.go +++ b/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) } diff --git a/src/website/requesthandling.go b/src/website/requesthandling.go index b0028a3..1daacdf 100644 --- a/src/website/requesthandling.go +++ b/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) }) } diff --git a/src/website/routes.go b/src/website/routes.go index 19872b7..7bf87ef 100644 --- a/src/website/routes.go +++ b/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,16 +199,18 @@ 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) - if err != nil { - return false, ErrorResponse(http.StatusInternalServerError, oops.New(err, "failed to get current user")) - } + { + sessionCookie, err := c.Req.Cookie(auth.SessionCookieName) + if err == nil { + user, err := getCurrentUser(c, sessionCookie.Value) + if err != nil { + return false, ErrorResponse(http.StatusInternalServerError, oops.New(err, "failed to get current user")) + } - c.CurrentUser = user + c.CurrentUser = user + } + // http.ErrNoCookie is the only error Cookie ever returns, so no further handling to do here. } - // http.ErrNoCookie is the only error Cookie ever returns, so no further handling to do here. return true, ResponseData{} } diff --git a/src/website/website.go b/src/website/website.go index 8b4d0ca..350f035 100644 --- a/src/website/website.go +++ b/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)