From 7846c5dfe99823fb332fb95ba60f74d51c9cdf83 Mon Sep 17 00:00:00 2001 From: Azareal Date: Fri, 14 May 2021 17:56:54 +1000 Subject: [PATCH] Add TickWatch. Add Log4thLongRoute dev setting. Reduce boilerplate. --- common/site.go | 1 + common/tickloop.go | 97 ++++++++++++++++++++++++++++++++++++++++++++++ main.go | 63 +++++++++++++++++------------- tickloop.go | 25 +++++++++++- 4 files changed, 159 insertions(+), 27 deletions(-) diff --git a/common/site.go b/common/site.go index 12c0578d..5febbe6a 100644 --- a/common/site.go +++ b/common/site.go @@ -160,6 +160,7 @@ type devConfig struct { //ExpFix1 bool // unlisted setting, experimental fix for http/1.1 conn hangs LogLongTick bool // unlisted setting LogNewLongRoute bool // unlisted setting + Log4thLongRoute bool // unlisted setting } // configHolder is purely for having a big struct to unmarshal data into diff --git a/common/tickloop.go b/common/tickloop.go index 6af419da..2f0980c5 100644 --- a/common/tickloop.go +++ b/common/tickloop.go @@ -1,12 +1,15 @@ package common import ( + "fmt" "log" "strconv" + "strings" "sync/atomic" "time" qgen "github.com/Azareal/Gosora/query_gen" + "github.com/Azareal/Gosora/uutils" "github.com/pkg/errors" ) @@ -215,3 +218,97 @@ func Dailies() (e error) { return nil } + +type TickWatch struct { + Name string + Start int64 + DBCheck int64 + StartHook int64 + Tasks int64 + EndHook int64 + + Ticker *time.Ticker + Deadline *time.Ticker + EndChan chan bool +} + +func NewTickWatch() *TickWatch { + return &TickWatch{ + Ticker: time.NewTicker(time.Second * 5), + Deadline: time.NewTicker(time.Hour), + } +} + +func (w *TickWatch) DumpElapsed() { + var sb strings.Builder + f := func(str string) { + sb.WriteString(str) + } + ff := func(str string, args ...interface{}) { + f(fmt.Sprintf(str, args...)) + } + secs := func(name string, bef, v int64) { + if bef == 0 || v == 0 { + ff("%s: %d\n", v) + } + ff("%s: %d - %.2f secs\n", name, v, time.Duration(bef-v).Seconds()) + } + + f("Name: " + w.Name + "\n") + ff("Start: %d\n", w.Start) + secs("DBCheck", w.Start, w.DBCheck) + secs("StartHook", w.DBCheck, w.StartHook) + secs("Tasks", w.StartHook, w.Tasks) + secs("EndHook", w.Tasks, w.EndHook) + + Log(sb.String()) +} + +func (w *TickWatch) Run() { + w.EndChan = make(chan bool) + // Use a goroutine to circumvent ticks which never end + go func() { + defer w.Ticker.Stop() + defer close(w.EndChan) + defer EatPanics() + var n int + for { + select { + case <-w.Ticker.C: + Logf("%d seconds elapsed since tick %s started", 5*n, w.Name) + n++ + case <-w.Deadline.C: + Log("Hit TickWatch deadline") + dur := time.Duration(uutils.Nanotime() - w.Start) + if dur.Seconds() > 5 { + Log("tick " + w.Name + " has run for " + dur.String()) + w.DumpElapsed() + } + return + case <-w.EndChan: + dur := time.Duration(uutils.Nanotime() - w.Start) + if dur.Seconds() > 5 { + Log("tick " + w.Name + " completed in " + dur.String()) + w.DumpElapsed() + } + return + } + } + }() +} + +func (w *TickWatch) Stop() { + w.EndChan <- true +} + +func (w *TickWatch) Set(a *int64, v int64) { + atomic.StoreInt64(a, v) +} + +func (w *TickWatch) Clear() { + w.Start = 0 + w.DBCheck = 0 + w.StartHook = 0 + w.Tasks = 0 + w.EndHook = 0 +} diff --git a/main.go b/main.go index 2efebab0..2b34d1dc 100644 --- a/main.go +++ b/main.go @@ -33,6 +33,7 @@ import ( _ "github.com/Azareal/Gosora/extend" qgen "github.com/Azareal/Gosora/query_gen" "github.com/Azareal/Gosora/routes" + "github.com/Azareal/Gosora/uutils" "github.com/fsnotify/fsnotify" //"github.com/lucas-clemente/quic-go/http3" @@ -602,15 +603,32 @@ func main() { sig := <-sigs log.Print("Received a signal to shutdown: ", sig) // TODO: Gracefully shutdown the HTTP server - if e := runHook("before_shutdown_tick"); e != nil { - log.Print("before_shutdown_tick err:", e) - } - log.Print("Running shutdown tasks") - c.Tasks.Shutdown.Run() - log.Print("Ran shutdown tasks") - if e := runHook("after_shutdown_tick"); e != nil { - log.Print("after_shutdown_tick err:", e) + tw, cn := c.NewTickWatch(), uutils.Nanotime() + tw.Name = "shutdown" + tw.Set(&tw.Start, cn) + tw.Set(&tw.DBCheck, cn) + tw.Run() + n, e := func() (string, error) { + if e := runHook("before_shutdown_tick"); e != nil { + return "before_shutdown_tick ", e + } + tw.Set(&tw.StartHook, uutils.Nanotime()) + log.Print("Running shutdown tasks") + if e := c.Tasks.Shutdown.Run(); e != nil { + return "shutdown tasks ", e + } + tw.Set(&tw.Tasks, uutils.Nanotime()) + log.Print("Ran shutdown tasks") + if e := runHook("after_shutdown_tick"); e != nil { + return "after_shutdown_tick ", e + } + tw.Set(&tw.EndHook, uutils.Nanotime()) + return "", nil + }() + if e != nil { + log.Print(n+" err:", e) } + tw.Stop() log.Print("Stopping server") c.StoppedServer("Stopped server") }() @@ -650,26 +668,19 @@ func main() { } func startServer() { - // We might not need the timeouts, if we're behind a reverse-proxy like Nginx + // We might not need timeouts, if we're behind a reverse-proxy like Nginx newServer := func(addr string, h http.Handler) *http.Server { - rtime := c.Config.ReadTimeout - if rtime == 0 { - rtime = 8 - } else if rtime == -1 { - rtime = 0 - } - wtime := c.Config.WriteTimeout - if wtime == 0 { - wtime = 10 - } else if wtime == -1 { - wtime = 0 - } - itime := c.Config.IdleTimeout - if itime == 0 { - itime = 120 - } else if itime == -1 { - itime = 0 + f := func(timeout, dval int) int { + if timeout == 0 { + timeout = dval + } else if timeout == -1 { + timeout = 0 + } + return timeout } + rtime := f(c.Config.ReadTimeout, 8) + wtime := f(c.Config.WriteTimeout, 10) + itime := f(c.Config.IdleTimeout, 120) return &http.Server{ Addr: addr, Handler: h, diff --git a/tickloop.go b/tickloop.go index 2e70a84a..b62e51af 100644 --- a/tickloop.go +++ b/tickloop.go @@ -60,18 +60,30 @@ func tickLoop(thumbChan chan bool) error { } tick := func(name string, tasks c.TaskSet, secs int) error { + tw := c.NewTickWatch() + tw.Name = name + tw.Set(&tw.Start, uutils.Nanotime()) + tw.Run() + defer tw.Stop() if c.StartTick() { return nil } + tw.Set(&tw.DBCheck, uutils.Nanotime()) if e := runHook("before_" + name + "_tick"); e != nil { return e } cn := uutils.Nanotime() + tw.Set(&tw.StartHook, cn) if e := tasks.Run(); e != nil { return e } + tw.Set(&tw.Tasks, uutils.Nanotime()) handleLogLongTick(name, cn, secs) - return runHook("after_" + name + "_tick") + if e := runHook("after_" + name + "_tick"); e != nil { + return e + } + tw.Set(&tw.EndHook, uutils.Nanotime()) + return nil } tl.HalfSecf = func() error { @@ -220,6 +232,8 @@ func sched() error { return nil } +var pingLastTopicCount = 1 + // TODO: Move somewhere else func PingLastTopicTick() error { g, e := c.Groups.Get(c.GuestUser.Group) @@ -258,6 +272,15 @@ func PingLastTopicTick() error { dur := time.Duration(uutils.Nanotime() - cn) if dur.Seconds() > 5 { c.Log("topic " + sid + " completed in " + dur.String()) + } else if c.Dev.Log4thLongRoute { + pingLastTopicCount++ + if pingLastTopicCount == 4 { + c.Log("topic " + sid + " completed in " + dur.String()) + } + if pingLastTopicCount >= 4 { + pingLastTopicCount = 1 + } } + return nil }