chore: add slow diff log

db/models/config_item.go

@@ -48,6 +48,17 @@ type ConfigItem struct {
 	ProbableParents []string               `gorm:"-" json:"-"`
 }
 
+func (ci ConfigItem) Label() string {
+	if len(ci.ExternalID) == 0 {
+		return fmt.Sprintf("%s/%s id=%s ", lo.FromPtr(ci.Type), lo.FromPtr(ci.Name), ci.ID)
+	}
+	if ci.ID == ci.ExternalID[0] {
+		return fmt.Sprintf("%s/%s id=%s", lo.FromPtr(ci.Type), lo.FromPtr(ci.Name), ci.ID)
+	}
+
+	return fmt.Sprintf("%s/%s id=%s external=%s", lo.FromPtr(ci.Type), lo.FromPtr(ci.Name), ci.ID, ci.ExternalID[0])
+}
+
 func (ci ConfigItem) String() string {
 	if len(ci.ExternalID) == 0 {
 		return fmt.Sprintf("id=%s type=%s name=%s ", ci.ID, lo.FromPtr(ci.Type), lo.FromPtr(ci.Name))

db/update.go

@@ -13,6 +13,8 @@ import (
 	jsonpatch "github.com/evanphx/json-patch"
 	"github.com/flanksource/commons/collections"
 	"github.com/flanksource/commons/logger"
+	"github.com/flanksource/commons/text"
+	"github.com/flanksource/commons/timer"
 	cUtils "github.com/flanksource/commons/utils"
 	"github.com/flanksource/config-db/api"
 	v1 "github.com/flanksource/config-db/api/v1"
@@ -674,11 +676,44 @@ func generateConfigChange(ctx api.ScrapeContext, newConf, prev models.ConfigItem
 		}
 	}
 
+	var _timer *timer.MemoryTimer
+	if ctx.Properties().On(false, "scraper.log.items") {
+		ctx.Logger.V(5).Infof("generating diff for %s", newConf.Label())
+	}
+	if ctx.Logger.IsLevelEnabled(4) && len(*newConf.Config) > ctx.Properties().Int("scraper.diff.timer.minSize", 1024*20) {
+		_timer = lo.ToPtr(timer.NewMemoryTimer())
+	}
+
+	start := time.Now()
+
 	diff, err := GenerateDiff(ctx.Context, *newConf.Config, *prev.Config)
 	if err != nil {
 		return nil, fmt.Errorf("failed to generate diff: %w", err)
 	}
 
+	duration := time.Since(start)
+
+	ctx.Histogram("scraper_diff_duration",
+		[]float64{1, 10, 100, 1000, 10000}, "scraper", ctx.ScrapeConfig().GetPersistedID().String()).
+		Record(time.Duration(duration.Milliseconds()))
+
+	msg := fmt.Sprintf("generated in %dms for %s size=%s diff=%s",
+		duration.Milliseconds(),
+		newConf.Label(),
+		text.HumanizeBytes(len(*newConf.Config)),
+		text.HumanizeBytes(len(diff)),
+	)
+	if _timer != nil {
+		msg += " " + _timer.End()
+	}
+	if duration > 500*time.Millisecond {
+		ctx.Logger.Warnf("SLOW DIFF >= %s", msg)
+	} else if duration > 50*time.Millisecond {
+		ctx.Logger.Infof("SLOW DIFF >= %s", msg)
+	} else if ctx.Properties().On(false, "scraper.log.items") {
+		ctx.Logger.V(4).Infof(msg)
+	}
+
 	if diff == "" {
 		return nil, nil
 	}

scrapers/kubernetes/informers.go

@@ -61,7 +61,9 @@ func (t *SharedInformerManager) Register(ctx api.ScrapeContext, watchResource v1
 				return
 			}
 
-			ctx.Logger.V(3).Infof("added: %s %s %s", u.GetUID(), u.GetKind(), u.GetName())
+			if ctx.Properties().On(false, "scraper.log.items") {
+				ctx.Logger.V(4).Infof("added: %s %s %s", u.GetUID(), u.GetKind(), u.GetName())
+			}
 			buffer <- u
 		},
 		UpdateFunc: func(oldObj any, newObj any) {
@@ -71,7 +73,9 @@ func (t *SharedInformerManager) Register(ctx api.ScrapeContext, watchResource v1
 				return
 			}
 
-			ctx.Logger.V(3).Infof("updated: %s %s %s", u.GetUID(), u.GetKind(), u.GetName())
+			if ctx.Properties().On(false, "scraper.log.items") {
+				ctx.Logger.V(3).Infof("updated: %s %s %s", u.GetUID(), u.GetKind(), u.GetName())
+			}
 			buffer <- u
 		},
 		DeleteFunc: func(obj any) {
@@ -81,7 +85,9 @@ func (t *SharedInformerManager) Register(ctx api.ScrapeContext, watchResource v1
 				return
 			}
 
-			ctx.Logger.V(3).Infof("deleted: %s %s %s", u.GetUID(), u.GetKind(), u.GetName())
+			if ctx.Properties().On(false, "scraper.log.items") {
+				ctx.Logger.V(3).Infof("deleted: %s %s %s", u.GetUID(), u.GetKind(), u.GetName())
+			}
 			deleteBuffer <- string(u.GetUID())
 		},
 	})