From 7a05941ea01437fc0c823a42da99f0d1554b495d Mon Sep 17 00:00:00 2001
From: Artur Wierzbicki <wierzbicki.artur.94@gmail.com>
Date: Mon, 16 May 2022 18:09:46 -0700
Subject: [PATCH] Previews: improve logging, add time measurements to the
 crawler (#49043)

* #44449: log times taken for various things in previews service / crawler

* #44449: remove stale log
---
 pkg/services/thumbs/crawler.go | 21 +++++++++++++--------
 pkg/services/thumbs/service.go |  9 +++++++--
 2 files changed, 20 insertions(+), 10 deletions(-)

diff --git a/pkg/services/thumbs/crawler.go b/pkg/services/thumbs/crawler.go
index 7e65a3590cf..2d146947da0 100644
--- a/pkg/services/thumbs/crawler.go
+++ b/pkg/services/thumbs/crawler.go
@@ -131,6 +131,8 @@ func (r *simpleCrawler) Run(ctx context.Context, auth CrawlerAuth, mode CrawlerM
 			"current version: %s, requiredVersion: %s", r.renderService.Version(), res.SemverConstraint)
 	}
 
+	runStarted := time.Now()
+
 	r.queueMutex.Lock()
 	if r.IsRunning() {
 		r.queueMutex.Unlock()
@@ -138,8 +140,6 @@ func (r *simpleCrawler) Run(ctx context.Context, auth CrawlerAuth, mode CrawlerM
 		return nil
 	}
 
-	now := time.Now()
-
 	items, err := r.thumbnailRepo.findDashboardsWithStaleThumbnails(ctx, theme, thumbnailKind)
 	if err != nil {
 		r.log.Error("Error when fetching dashboards with stale thumbnails", "err", err.Error())
@@ -171,14 +171,14 @@ func (r *simpleCrawler) Run(ctx context.Context, auth CrawlerAuth, mode CrawlerM
 	r.renderingSessionByOrgId = make(map[int64]rendering.Session)
 	r.queue = items
 	r.status = crawlStatus{
-		Started:  now,
+		Started:  runStarted,
 		State:    running,
 		Complete: 0,
 	}
 	r.broadcastStatus()
 	r.queueMutex.Unlock()
 
-	r.log.Info("Starting dashboard crawler", "dashboardsToCrawl", len(items), "mode", string(mode), "theme", string(theme), "kind", string(thumbnailKind))
+	r.log.Info("Starting dashboard crawler", "threadCount", r.threadCount, "dashboardsToCrawl", len(items), "mode", string(mode), "theme", string(theme), "kind", string(thumbnailKind), "crawlerSetupTime", time.Since(runStarted))
 
 	group, gCtx := errgroup.WithContext(ctx)
 	// create a pool of workers
@@ -191,6 +191,9 @@ func (r *simpleCrawler) Run(ctx context.Context, auth CrawlerAuth, mode CrawlerM
 	}
 
 	err = group.Wait()
+
+	status, _ := r.Status()
+	r.log.Info("Crawl finished", "completedCount", status.Complete, "errorCount", status.Errors, "threadCount", r.threadCount, "dashboardsToCrawl", len(items), "mode", string(mode), "theme", string(theme), "kind", string(thumbnailKind), "crawlerRunTime", time.Since(runStarted))
 	if err != nil {
 		r.log.Error("Crawl ended with an error", "err", err)
 	}
@@ -253,7 +256,6 @@ func (r *simpleCrawler) crawlFinished() {
 
 	r.status.State = stopped
 	r.status.Finished = time.Now()
-	r.log.Info("Crawler finished", "startTime", r.status.Started, "endTime", r.status.Finished, "durationInSeconds", int64(time.Since(r.status.Started)/time.Second))
 }
 
 func (r *simpleCrawler) shouldWalk() bool {
@@ -264,11 +266,14 @@ func (r *simpleCrawler) shouldWalk() bool {
 }
 
 func (r *simpleCrawler) walk(ctx context.Context, id int) {
+	walkerStarted := time.Now()
+
 	for {
 		if !r.shouldWalk() {
 			break
 		}
 
+		itemStarted := time.Now()
 		item, renderingSession, authOpts, err := r.next(ctx)
 		if err != nil {
 			r.log.Error("Render item retrieval error", "walkerId", id, "error", err)
@@ -319,10 +324,10 @@ func (r *simpleCrawler) walk(ctx context.Context, id int) {
 				}, item.Version)
 
 				if err != nil {
-					r.log.Warn("Error saving image image", "walkerId", id, "dashboardUID", item.Uid, "url", url, "err", err)
+					r.log.Warn("Error saving image image", "walkerId", id, "dashboardUID", item.Uid, "url", url, "err", err, "itemTime", time.Since(itemStarted))
 					r.newErrorResult()
 				} else {
-					r.log.Info("Saved thumbnail", "walkerId", id, "dashboardUID", item.Uid, "url", url, "thumbnailId", thumbnailId)
+					r.log.Info("Saved thumbnail", "walkerId", id, "dashboardUID", item.Uid, "url", url, "thumbnailId", thumbnailId, "itemTime", time.Since(itemStarted))
 					r.newSuccessResult()
 				}
 			}()
@@ -330,5 +335,5 @@ func (r *simpleCrawler) walk(ctx context.Context, id int) {
 		r.broadcastStatus()
 	}
 
-	r.log.Info("Walker finished", "walkerId", id)
+	r.log.Info("Walker finished", "walkerId", id, "walkerTime", time.Since(walkerStarted))
 }
diff --git a/pkg/services/thumbs/service.go b/pkg/services/thumbs/service.go
index 165d413bdfb..b1c72334bbd 100644
--- a/pkg/services/thumbs/service.go
+++ b/pkg/services/thumbs/service.go
@@ -71,15 +71,20 @@ func ProvideService(cfg *setting.Cfg, features featuremgmt.FeatureToggles, lockS
 	}
 	logger := log.New("previews_service")
 
-	logger.Info("initialized thumb", "settings", cfg.DashboardPreviews)
 	thumbnailRepo := newThumbnailRepo(store)
 
 	canRunCrawler := true
+
+	authSetupStarted := time.Now()
 	crawlerAuth, err := authSetupService.Setup(context.Background())
+
 	if err != nil {
-		logger.Error("failed to setup auth for the dashboard previews crawler", "err", err)
+		logger.Error("Crawler auth setup failed", "err", err, "crawlerAuthSetupTime", time.Since(authSetupStarted))
 		canRunCrawler = false
+	} else {
+		logger.Info("Crawler auth setup complete", "crawlerAuthSetupTime", time.Since(authSetupStarted))
 	}
+
 	t := &thumbService{
 		renderingService:           renderService,
 		renderer:                   newSimpleCrawler(renderService, gl, thumbnailRepo, cfg, cfg.DashboardPreviews),