Add TickWatch.

Add Log4thLongRoute dev setting.
Reduce boilerplate.

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

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
+}

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
+		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 {
-			log.Print("before_shutdown_tick err:", e)
+				return "before_shutdown_tick ", e
 			}
+			tw.Set(&tw.StartHook, uutils.Nanotime())
 			log.Print("Running shutdown tasks")
-		c.Tasks.Shutdown.Run()
+			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 {
-			log.Print("after_shutdown_tick err:", e)
+				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
+		f := func(timeout, dval int) int {
-		if rtime == 0 {
+			if timeout == 0 {
-			rtime = 8
+				timeout = dval
-		} else if rtime == -1 {
+			} else if timeout == -1 {
-			rtime = 0
+				timeout = 0
 			}
-		wtime := c.Config.WriteTimeout
+			return timeout
-		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
 		}
+		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,

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
 }