Log metrics

Author: jesusfcr

pkg/store/sources.go

@@ -13,6 +13,7 @@ import (
 	"time"
 
 	"github.com/jmoiron/sqlx"
+	log "github.com/sirupsen/logrus"
 )
 
 // Source represents a source
@@ -119,6 +120,7 @@ func (db *psqlxStore) ProcessSourceExecution(s Source, sourceFindings []SourceFi
 	if screated == nil {
 		return Source{}, errors.New("unexpected nil pointer after source creation")
 	}
+	tInit := time.Now()
 
 	// Before updating the findings we have to lock the tx to prevent race
 	// conditions from other possible concurrent sources being processed.
@@ -133,6 +135,7 @@ func (db *psqlxStore) ProcessSourceExecution(s Source, sourceFindings []SourceFi
 		return Source{}, err
 	}
 
+	tRelatedFamilies := time.Now()
 	for _, sf := range sourceFindings {
 		err = createSourceIssue(ctx, tx, sf.IssueID, screated.ID)
 		if err != nil {
@@ -162,6 +165,7 @@ func (db *psqlxStore) ProcessSourceExecution(s Source, sourceFindings []SourceFi
 		}
 	}
 
+	tFindings := time.Now()
 	findingStates, err := findingsStates(ctx, tx, db.logger, screated.SourceFamily)
 	if err != nil {
 		tx.Rollback()
@@ -174,6 +178,18 @@ func (db *psqlxStore) ProcessSourceExecution(s Source, sourceFindings []SourceFi
 		return Source{}, err
 	}
 
+	db.logger.WithFields(log.Fields{
+		"msRelatedFamilies": tRelatedFamilies.Sub(tInit).Milliseconds(),
+		"msFindings":        tFindings.Sub(tRelatedFamilies).Milliseconds(),
+		"msFindingStates":   time.Since(tFindings).Milliseconds(),
+		"msTotal":           time.Since(tInit).Milliseconds(),
+		"numFindingStates":  len(findingStates),
+		"numSourceFindings": len(sourceFindings),
+		"target":            s.Target,
+		"check":             s.Instance,
+		"component":         s.Component,
+	}).Info("ProcessSourceExecution")
+
 	return *screated, tx.Commit()
 }