metrics and logs for long app start

app/app.go

@@ -46,6 +46,7 @@ type ComponentRunnable interface {
 type App struct {
 	components []Component
 	mu         sync.RWMutex
+	startStat  StartStat
 }
 
 // Name returns app name
@@ -58,6 +59,18 @@ func (app *App) Version() string {
 	return GitSummary
 }
 
+type StartStat struct {
+	SpentMsPerComp map[string]int64
+	SpentMsTotal   int64
+}
+
+// StartStat returns total time spent per comp
+func (app *App) StartStat() StartStat {
+	app.mu.Lock()
+	defer app.mu.Unlock()
+	return app.startStat
+}
+
 // VersionDescription return the full info about the build
 func (app *App) VersionDescription() string {
 	return VersionDescription()
@@ -123,6 +136,7 @@ func (app *App) ComponentNames() (names []string) {
 func (app *App) Start() (err error) {
 	app.mu.RLock()
 	defer app.mu.RUnlock()
+	app.startStat.SpentMsPerComp = make(map[string]int64)
 
 	closeServices := func(idx int) {
 		for i := idx; i >= 0; i-- {
@@ -149,6 +163,9 @@ func (app *App) Start() (err error) {
 				closeServices(i)
 				return fmt.Errorf("can't run service '%s': %v", serviceRun.Name(), err)
 			}
+			spent := time.Since(start).Milliseconds()
+			app.startStat.SpentMsTotal += spent
+			app.startStat.SpentMsPerComp[s.Name()] = spent
 		}
 	}
 	log.Debugf("All components started")

core/account.go

@@ -17,6 +17,7 @@ import (
 	"github.com/anytypeio/go-anytype-middleware/core/anytype"
 	"github.com/anytypeio/go-anytype-middleware/core/block"
 	"github.com/anytypeio/go-anytype-middleware/core/configfetcher"
+	"github.com/anytypeio/go-anytype-middleware/metrics"
 	"github.com/anytypeio/go-anytype-middleware/pb"
 	"github.com/anytypeio/go-anytype-middleware/pkg/lib/core"
 	"github.com/anytypeio/go-anytype-middleware/pkg/lib/pb/model"
@@ -188,6 +189,16 @@ func (mw *Middleware) AccountCreate(req *pb.RpcAccountCreateRequest) *pb.RpcAcco
 		return response(newAcc, pb.RpcAccountCreateResponseError_ACCOUNT_CREATED_BUT_FAILED_TO_START_NODE, err)
 	}
 
+	stat := mw.app.StartStat()
+	if stat.SpentMsTotal > 300 {
+		log.Errorf("AccountCreate app start takes %dms: %v", stat.SpentMsTotal, stat.SpentMsPerComp)
+	}
+
+	metrics.SharedClient.RecordEvent(metrics.AppStart{
+		Type:      "create",
+		TotalMs:   stat.SpentMsTotal,
+		PerCompMs: stat.SpentMsPerComp})
+
 	coreService := mw.app.MustComponent(core.CName).(core.Service)
 	newAcc.Name = req.Name
 	bs := mw.app.MustComponent(block.CName).(block.Service)
@@ -476,6 +487,16 @@ func (mw *Middleware) AccountSelect(req *pb.RpcAccountSelectRequest) *pb.RpcAcco
 		return response(nil, pb.RpcAccountSelectResponseError_FAILED_TO_RUN_NODE, err)
 	}
 
+	stat := mw.app.StartStat()
+	if stat.SpentMsTotal > 300 {
+		log.Errorf("AccountSelect app start takes %dms: %v", stat.SpentMsTotal, stat.SpentMsPerComp)
+	}
+
+	metrics.SharedClient.RecordEvent(metrics.AppStart{
+		Type:      "select",
+		TotalMs:   stat.SpentMsTotal,
+		PerCompMs: stat.SpentMsPerComp})
+
 	return response(&model.Account{Id: req.Id}, pb.RpcAccountSelectResponseError_NULL, nil)
 }
 

core/anytype/bootstrap.go

@@ -80,6 +80,7 @@ func StartNewApp(components ...app.Component) (a *app.App, err error) {
 		a = nil
 		return
 	}
+
 	return
 }
 

metrics/events.go

@@ -226,6 +226,23 @@ func (c StateApply) ToEvent() Event {
 	}
 }
 
+type AppStart struct {
+	Type      string
+	TotalMs   int64
+	PerCompMs map[string]int64
+}
+
+func (c AppStart) ToEvent() Event {
+	return Event{
+		EventType: "app_start",
+		EventData: map[string]interface{}{
+			"type":     c.Type,
+			"time_ms":  c.TotalMs,
+			"per_comp": c.PerCompMs,
+		},
+	}
+}
+
 type InitPredefinedBlocks struct {
 	TimeMs int64
 }