feat(analytics) print CPU and Memory usage in logs (#2379)

go.mod

@@ -10,6 +10,7 @@ require (
 	github.com/getsentry/sentry-go v0.10.0
 	github.com/golang/mock v1.5.0
 	github.com/google/go-cmp v0.5.4 // indirect
+	github.com/google/pprof v0.0.0-20210413054141-7c2eacd09c8d
 	github.com/google/uuid v1.2.0
 	github.com/gookit/color v1.4.2
 	github.com/gregjones/httpcache v0.0.0-20190611155906-901d90724c79 // indirect

go.sum

@@ -590,7 +590,10 @@ github.com/google/pprof v0.0.0-20190515194954-54271f7e092f/go.mod h1:zfwlbNMJ+OI
 github.com/google/pprof v0.0.0-20191218002539-d4f498aebedc/go.mod h1:ZgVRPoUq/hfqzAqh7sHMqb3I9Rq5C59dIz2SbBwJ4eM=
 github.com/google/pprof v0.0.0-20200212024743-f11f1df84d12/go.mod h1:ZgVRPoUq/hfqzAqh7sHMqb3I9Rq5C59dIz2SbBwJ4eM=
 github.com/google/pprof v0.0.0-20200229191704-1ebb73c60ed3/go.mod h1:ZgVRPoUq/hfqzAqh7sHMqb3I9Rq5C59dIz2SbBwJ4eM=
+github.com/google/pprof v0.0.0-20200430221834-fc25d7d30c6d h1:iaAPcMIY2f+gpk8tKf0BMW5sLrlhaASiYAnFmvVG5e0=
 github.com/google/pprof v0.0.0-20200430221834-fc25d7d30c6d/go.mod h1:ZgVRPoUq/hfqzAqh7sHMqb3I9Rq5C59dIz2SbBwJ4eM=
+github.com/google/pprof v0.0.0-20210413054141-7c2eacd09c8d h1:X4vWSRcXmxBANxWPGUsfWv291lZUjENBew0l1R/RVRk=
+github.com/google/pprof v0.0.0-20210413054141-7c2eacd09c8d/go.mod h1:kpwsk12EmLew5upagYY7GY0pfYCcupk39gWOCRROcvE=
 github.com/google/renameio v0.1.0/go.mod h1:KWCgfxg9yswjAJkECMjeO8J8rahYeXnNhOm40UhjYkI=
 github.com/google/rpmpack v0.0.0-20191226140753-aa36bfddb3a0/go.mod h1:RaTPr0KUf2K7fnZYLNDrr8rxAamWs3iNywJLtQ2AzBg=
 github.com/google/shlex v0.0.0-20191202100458-e7afc7fbc510/go.mod h1:pupxD2MaaD3pAXIBCelhxNneeOaAeabZDe5s4K6zSpQ=
@@ -691,7 +694,9 @@ github.com/hpcloud/tail v1.0.0/go.mod h1:ab1qPbhIpdTxEkNHXyeSf5vhxWSCs/tWer42PpO
 github.com/huandu/xstrings v1.3.1 h1:4jgBlKK6tLKFvO8u5pmYjG91cqytmDCDvGh7ECVFfFs=
 github.com/huandu/xstrings v1.3.1/go.mod h1:y5/lhBue+AyNmUVz9RLU9xbLR0o4KIIExikq4ovT0aE=
 github.com/hudl/fargo v1.3.0/go.mod h1:y3CKSmjA+wD2gak7sUSXTAoopbhU08POFhmITJgmKTg=
+github.com/ianlancetaylor/demangle v0.0.0-20181102032728-5e5cf60278f6 h1:UDMh68UUwekSh5iP2OMhRRZJiiBccgV7axzUG8vi56c=
 github.com/ianlancetaylor/demangle v0.0.0-20181102032728-5e5cf60278f6/go.mod h1:aSSvb/t6k1mPoxDqO4vJh6VOCGPwU4O0C2/Eqndh1Sc=
+github.com/ianlancetaylor/demangle v0.0.0-20200824232613-28f6c0f3b639/go.mod h1:aSSvb/t6k1mPoxDqO4vJh6VOCGPwU4O0C2/Eqndh1Sc=
 github.com/imdario/mergo v0.3.5/go.mod h1:2EnlNZ0deacrJVfApfmtdGgDfMuh/nq6Ok1EcJh5FfA=
 github.com/imdario/mergo v0.3.8/go.mod h1:2EnlNZ0deacrJVfApfmtdGgDfMuh/nq6Ok1EcJh5FfA=
 github.com/imdario/mergo v0.3.9/go.mod h1:2EnlNZ0deacrJVfApfmtdGgDfMuh/nq6Ok1EcJh5FfA=

internal/console/helpers/helpers.go

@@ -12,6 +12,7 @@ import (
 	"sync"
 
 	"github.com/BurntSushi/toml"
+	"github.com/Checkmarx/kics/internal/global"
 	"github.com/Checkmarx/kics/pkg/model"
 	"github.com/Checkmarx/kics/pkg/report"
 	"github.com/gookit/color"
@@ -244,13 +245,15 @@ func FileAnalyzer(path string) (string, error) {
 // GenerateReport execute each report function to generate report
 func GenerateReport(path, filename string, body interface{}, formats []string) error {
 	log.Debug().Msgf("helpers.GenerateReport()")
+	global.Metric.Start("generate_report")
 	var err error = nil
 	for _, format := range formats {
 		if err = reportGenerators[format](path, filename, body); err != nil {
 			log.Error().Msgf("Failed to generate %s report", format)
 			break
 		}
 	}
+	global.Metric.Stop()
 	return err
 }
 

internal/console/kics.go

@@ -31,6 +31,7 @@ var (
 	noColor   bool
 	silent    bool
 	ci        bool
+	metric    string
 
 	warning []string
 )
@@ -89,9 +90,17 @@ func initialize(rootCmd *cobra.Command) error {
 		"",
 		false,
 		"display only log messages to CLI output (mutually exclusive with silent)")
+	rootCmd.PersistentFlags().StringVarP(&metric,
+		"metrics",
+		"",
+		"",
+		"display metrics for the steps of kics exucution (CPU, MEM)")
 
-	err := rootCmd.PersistentFlags().MarkDeprecated(printer.LogFileFlag, "please use --log-path instead")
-	if err != nil {
+	if err := rootCmd.PersistentFlags().MarkHidden("metrics"); err != nil {
+		return err
+	}
+
+	if err := rootCmd.PersistentFlags().MarkDeprecated(printer.LogFileFlag, "please use --log-path instead"); err != nil {
 		return err
 	}
 
@@ -132,7 +141,7 @@ func Execute() error {
 	}
 	defer sentry.Flush(timeMult * time.Second)
 
-	if err := initialize(rootCmd); err != nil {
+	if err = initialize(rootCmd); err != nil {
 		sentry.CaptureException(err)
 		log.Err(err).Msg("Failed to initialize CLI")
 		return err

internal/console/scan.go

@@ -11,6 +11,8 @@ import (
 	consoleHelpers "github.com/Checkmarx/kics/internal/console/helpers"
 	internalPrinter "github.com/Checkmarx/kics/internal/console/printer"
 	"github.com/Checkmarx/kics/internal/constants"
+	"github.com/Checkmarx/kics/internal/global"
+	"github.com/Checkmarx/kics/internal/metrics"
 	"github.com/Checkmarx/kics/internal/storage"
 	"github.com/Checkmarx/kics/internal/tracker"
 	"github.com/Checkmarx/kics/pkg/engine"
@@ -84,12 +86,17 @@ func NewScanCmd() *cobra.Command {
 		Use:   scanCommandStr,
 		Short: "Executes a scan analysis",
 		PersistentPreRunE: func(cmd *cobra.Command, args []string) error {
-			err := initializeConfig(cmd)
-			if err != nil {
+			if err := initializeConfig(cmd); err != nil {
+				return err
+			}
+			if err := internalPrinter.SetupPrinter(cmd.InheritedFlags()); err != nil {
 				return err
 			}
-			err = internalPrinter.SetupPrinter(cmd.InheritedFlags())
+			var err error
+			global.Metric, err = metrics.InitializeMetrics(cmd.InheritedFlags().Lookup("metrics"))
 			if err != nil {
+				sentry.CaptureException(err)
+				log.Err(err).Msg("Failed to initialize Metrics")
 				return err
 			}
 			return nil

internal/global/global.go

@@ -0,0 +1,12 @@
+package global
+
+import (
+	"github.com/Checkmarx/kics/internal/metrics"
+)
+
+var (
+	// Metric is the global metrics object
+	Metric = &metrics.Metrics{
+		Disable: true,
+	}
+)

internal/metrics/cpu_metric.go

@@ -0,0 +1,59 @@
+package metrics
+
+import (
+	"bytes"
+	"runtime/pprof"
+	"time"
+
+	"github.com/rs/zerolog/log"
+)
+
+type cpuMetric struct {
+	close   func()
+	writer  *bytes.Buffer
+	idx     int
+	typeMap map[string]float64
+}
+
+var cpuMap = map[string]float64{
+	"ns":  float64(time.Nanosecond),
+	"us":  float64(time.Microsecond),
+	"ms":  float64(time.Millisecond),
+	"s":   float64(time.Second),
+	"hrs": float64(time.Hour),
+}
+
+// Start - start gathering metrics for CPU usage
+func (c *cpuMetric) start() {
+	c.idx = 1
+	c.typeMap = cpuMap
+
+	c.writer = bytes.NewBuffer([]byte{})
+
+	if err := pprof.StartCPUProfile(c.writer); err != nil {
+		log.Error().Msgf("failed to write cpu profile")
+	}
+	c.close = func() {
+		pprof.StopCPUProfile()
+	}
+}
+
+// Stop - stop gathering metrics for CPU usage
+func (c *cpuMetric) stop() {
+	c.close()
+}
+
+// getWriter returns the profile buffer
+func (c *cpuMetric) getWriter() *bytes.Buffer {
+	return c.writer
+}
+
+// getIndex returns the cpu sample index
+func (c *cpuMetric) getIndex() int {
+	return c.idx
+}
+
+// getMap returns the map used to format total value
+func (c *cpuMetric) getMap() map[string]float64 {
+	return c.typeMap
+}

internal/metrics/mem_metric.go

@@ -0,0 +1,72 @@
+package metrics
+
+import (
+	"bytes"
+	"runtime"
+	"runtime/pprof"
+
+	"github.com/rs/zerolog/log"
+)
+
+type memMetric struct {
+	close   func()
+	writer  *bytes.Buffer
+	idx     int
+	typeMap map[string]float64
+}
+
+var (
+	b  = 1
+	kb = 10
+	mb = 20
+	gb = 30
+	tb = 40
+	pb = 50
+)
+
+var memoryMap = map[string]float64{
+	"B":  float64(b),
+	"kB": float64(b << kb),
+	"MB": float64(b << mb),
+	"GB": float64(b << gb),
+	"TB": float64(b << tb),
+	"PB": float64(b << pb),
+}
+
+// Start - start gathering metrics for Memory usage
+func (c *memMetric) start() {
+	c.idx = 3
+	c.typeMap = memoryMap
+
+	old := runtime.MemProfileRate
+	runtime.MemProfileRate = 4096 // set default memory rate
+
+	c.writer = bytes.NewBuffer([]byte{})
+	c.close = func() {
+		if err := pprof.Lookup("heap").WriteTo(c.writer, 0); err != nil {
+			log.Error().Msgf("failed to write mem profile")
+		}
+
+		runtime.MemProfileRate = old
+	}
+}
+
+// Stop - stop gathering metrics for Memory usage
+func (c *memMetric) stop() {
+	c.close()
+}
+
+// getWriter returns the profile buffer
+func (c *memMetric) getWriter() *bytes.Buffer {
+	return c.writer
+}
+
+// getIndex returns the memory sample index
+func (c *memMetric) getIndex() int {
+	return c.idx
+}
+
+// getMap returns the map used to format total value
+func (c *memMetric) getMap() map[string]float64 {
+	return c.typeMap
+}

internal/metrics/metrics.go

@@ -0,0 +1,128 @@
+package metrics
+
+import (
+	"bytes"
+	"fmt"
+	"strings"
+
+	"github.com/google/pprof/profile"
+	"github.com/rs/zerolog/log"
+	"github.com/spf13/pflag"
+)
+
+// Start - starts gathering metrics based on the type of metrics and writes metrics to string
+// Stop - stops gathering metrics for the type of metrics specified
+type metricType interface {
+	start()
+	stop()
+	getWriter() *bytes.Buffer
+	getIndex() int
+	getMap() map[string]float64
+}
+
+// Metrics - structure to keep information relevant to the metrics calculation
+// Disable - disables metric calculations
+type Metrics struct {
+	metric    metricType
+	metricsID string
+	location  string
+	Disable   bool
+}
+
+// InitializeMetrics - creates a new instance of a Metrics based on the type of metrics specified
+func InitializeMetrics(metric *pflag.Flag) (*Metrics, error) {
+	metricStr := metric.Value.String()
+	var err error
+	metrics := &Metrics{}
+	switch strings.ToLower(metricStr) {
+	case "cpu":
+		metrics.Disable = false
+		metrics.metric = &cpuMetric{}
+	case "mem":
+		metrics.metric = &memMetric{}
+		metrics.Disable = false
+	case "":
+		metrics.Disable = true
+	default:
+		metrics.Disable = true
+		err = fmt.Errorf("unknonwn metric: %s (available metrics: cpu, mem)", metricStr)
+	}
+
+	// Create temporary dir to keep pprof file
+	if !metrics.Disable {
+		metrics.metricsID = metricStr
+	}
+
+	return metrics, err
+}
+
+// Start - starts gathering metrics for the location specified
+func (m *Metrics) Start(location string) {
+	if m.Disable {
+		return
+	}
+
+	log.Debug().Msgf("Started %s profiling for %s", m.metricsID, location)
+
+	m.location = location
+	m.metric.start()
+}
+
+// Stop - stops gathering metrics and logs the result
+func (m *Metrics) Stop() {
+	if m.Disable {
+		return
+	}
+	log.Debug().Msgf("Stopped %s profiling for %s", m.metricsID, m.location)
+
+	m.metric.stop()
+
+	p, err := profile.Parse(m.metric.getWriter())
+	if err != nil {
+		log.Error().Msgf("failed to parse profile on %s: %s", m.location, err)
+	}
+
+	if err := p.CheckValid(); err != nil {
+		log.Error().Msgf("invalid profile on %s: %s", m.location, err)
+	}
+
+	total := getTotal(p, m.metric.getIndex())
+	log.Info().
+		Msgf("Total %s usage for %s: %s", strings.ToUpper(m.metricsID), m.location, formatTotal(total, m.metric.getMap()))
+}
+
+// Get total goes through the profile samples summing their values according to
+// the type of profile
+func getTotal(prof *profile.Profile, idx int) int64 {
+	var total, diffTotal int64
+	for _, sample := range prof.Sample {
+		var v int64
+		v = sample.Value[idx]
+		if v < 0 {
+			v = -v
+		}
+		total += v
+		if sample.DiffBaseSample() {
+			diffTotal += v
+		}
+	}
+	if diffTotal > 0 {
+		total = diffTotal
+	}
+
+	return total
+}
+
+// formatTotal parses total value into a human readble way
+func formatTotal(b int64, typeMap map[string]float64) string {
+	value := float64(b)
+	var formatter float64
+	var mesure string
+	for k, u := range typeMap {
+		if u >= formatter && (value/u) >= 1.0 {
+			formatter = u
+			mesure = k
+		}
+	}
+	return fmt.Sprintf("%.2f%s", value/formatter, mesure)
+}