Log validation and prevalidation times for blocks to files (#126)

.gitignore

@@ -2,3 +2,4 @@ main
 bin/
 GeoLite2-*.mmdb
 .idea/*
+*.log

cmd/root.go

@@ -35,6 +35,7 @@ func init() {
 		logLevel                          string
 		requestTimeout                    time.Duration
 		disableCentralHarvesterCollection bool
+		logBlockTimes bool
 	)
 
 	cobra.OnInitialize(initConfig)
@@ -46,13 +47,15 @@ func init() {
 	rootCmd.PersistentFlags().StringVar(&logLevel, "log-level", "info", "How verbose the logs should be. panic, fatal, error, warn, info, debug, trace")
 	rootCmd.PersistentFlags().DurationVar(&requestTimeout, "rpc-timeout", 10*time.Second, "How long RPC requests will wait before timing out")
 	rootCmd.PersistentFlags().BoolVar(&disableCentralHarvesterCollection, "disable-central-harvester-collection", false, "Disables collection of harvester information via the farmer. Useful for very large farms where this request is very expensive, or cases where chia-exporter is already installed on all harvesters")
+	rootCmd.PersistentFlags().BoolVar(&logBlockTimes, "log-block-times", false, "Enables logging of block (pre)validation times to log files.")
 
 	cobra.CheckErr(viper.BindPFlag("hostname", rootCmd.PersistentFlags().Lookup("hostname")))
 	cobra.CheckErr(viper.BindPFlag("metrics-port", rootCmd.PersistentFlags().Lookup("metrics-port")))
 	cobra.CheckErr(viper.BindPFlag("maxmind-db-path", rootCmd.PersistentFlags().Lookup("maxmind-db-path")))
 	cobra.CheckErr(viper.BindPFlag("log-level", rootCmd.PersistentFlags().Lookup("log-level")))
 	cobra.CheckErr(viper.BindPFlag("rpc-timeout", rootCmd.PersistentFlags().Lookup("rpc-timeout")))
 	cobra.CheckErr(viper.BindPFlag("disable-central-harvester-collection", rootCmd.PersistentFlags().Lookup("disable-central-harvester-collection")))
+	cobra.CheckErr(viper.BindPFlag("log-block-times", rootCmd.PersistentFlags().Lookup("log-block-times")))
 }
 
 // initConfig reads in config file and ENV variables if set.

internal/metrics/fullnode.go

@@ -12,6 +12,7 @@ import (
 	"github.com/chia-network/go-chia-libs/pkg/types"
 	"github.com/prometheus/client_golang/prometheus"
 	log "github.com/sirupsen/logrus"
+	"github.com/spf13/viper"
 
 	wrappedPrometheus "github.com/chia-network/go-modules/pkg/prometheus"
 
@@ -316,6 +317,15 @@ func (s *FullNodeServiceMetrics) Block(resp *types.WebsocketResponse) {
 	s.preValidationTime.Set(block.PreValidationTime)
 	s.validationTime.Set(block.ValidationTime)
 
+	if viper.GetBool("log-block-times") {
+		if err = utils.LogToFile("pre-validation-time.log", fmt.Sprintf("%d:%f", block.Height, block.PreValidationTime)); err != nil {
+			log.Error(err.Error())
+		}
+		if err = utils.LogToFile("validation-time.log", fmt.Sprintf("%d:%f", block.Height, block.ValidationTime)); err != nil {
+			log.Error(err.Error())
+		}
+	}
+
 	if block.TransactionBlock {
 		s.blockCost.Set(float64(block.BlockCost.OrEmpty()))
 		s.blockFees.Set(float64(block.BlockFees.OrEmpty()))

internal/utils/log.go

@@ -0,0 +1,33 @@
+package utils
+
+import (
+	"os"
+	"path/filepath"
+
+	"github.com/chia-network/go-chia-libs/pkg/config"
+	log "github.com/sirupsen/logrus"
+)
+
+// LogToFile logs a message to a given file
+func LogToFile(filename, message string) error {
+	rootPath, err := config.GetChiaRootPath()
+	if err != nil {
+		return err
+	}
+	path := filepath.Join(rootPath, "log", filename)
+	file, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
+	if err != nil {
+		return err
+	}
+	defer func(file *os.File) {
+		err := file.Close()
+		if err != nil {
+			log.Errorf("Error closing file: %s\n", err.Error())
+		}
+	}(file)
+
+	if _, err := file.WriteString(message + "\n"); err != nil {
+		return err
+	}
+	return nil
+}