cmd, core, metrics: always report expensive metrics (ethereum#29191)

* cmd, core, metrics: always report expensive metrics

* core, metrics: report block processing metrics as resetting timer

* metrics: update reporter tests

cmd/XDC/config.go

@@ -32,6 +32,7 @@ import (
 	"github.com/XinFinOrg/XDPoSChain/common"
 	"github.com/XinFinOrg/XDPoSChain/eth/ethconfig"
 	"github.com/XinFinOrg/XDPoSChain/internal/flags"
+	"github.com/XinFinOrg/XDPoSChain/log"
 	"github.com/XinFinOrg/XDPoSChain/metrics"
 	"github.com/XinFinOrg/XDPoSChain/node"
 	"github.com/XinFinOrg/XDPoSChain/params"
@@ -271,7 +272,7 @@ func applyMetricConfig(ctx *cli.Context, cfg *XDCConfig) {
 		cfg.Metrics.Enabled = ctx.Bool(utils.MetricsEnabledFlag.Name)
 	}
 	if ctx.IsSet(utils.MetricsEnabledExpensiveFlag.Name) {
-		cfg.Metrics.EnabledExpensive = ctx.Bool(utils.MetricsEnabledExpensiveFlag.Name)
+		log.Warn("Expensive metrics are collected by default, please remove this flag", "flag", utils.MetricsEnabledExpensiveFlag.Name)
 	}
 	if ctx.IsSet(utils.MetricsHTTPFlag.Name) {
 		cfg.Metrics.HTTP = ctx.String(utils.MetricsHTTPFlag.Name)

cmd/utils/flags.go

@@ -644,11 +644,6 @@ var (
 		Usage:    "Enable metrics collection and reporting",
 		Category: flags.MetricsCategory,
 	}
-	MetricsEnabledExpensiveFlag = &cli.BoolFlag{
-		Name:     "metrics-expensive",
-		Usage:    "Enable expensive metrics collection and reporting",
-		Category: flags.MetricsCategory,
-	}
 	// MetricsHTTPFlag defines the endpoint for a stand-alone metrics HTTP endpoint.
 	// Since the pprof service enables sensitive/vulnerable behavior, this allows a user
 	// to enable a public-OK metrics endpoint without having to worry about ALSO exposing

cmd/utils/flags_legacy.go

@@ -68,6 +68,12 @@ var (
 		Usage:    "Prepends log messages with call-site location (deprecated)",
 		Category: flags.DeprecatedCategory,
 	}
+	// Deprecated February 2024
+	MetricsEnabledExpensiveFlag = &cli.BoolFlag{
+		Name:     "metrics-expensive",
+		Usage:    "Enable expensive metrics collection and reporting (deprecated)",
+		Category: flags.DeprecatedCategory,
+	}
 )
 
 // showDeprecated displays deprecated flags that will be soon removed from the codebase.

core/blockchain.go

@@ -62,20 +62,20 @@ var (
 
 	chainInfoGauge = metrics.NewRegisteredGaugeInfo("chain/info", nil)
 
-	accountReadTimer   = metrics.NewRegisteredTimer("chain/account/reads", nil)
-	accountHashTimer   = metrics.NewRegisteredTimer("chain/account/hashes", nil)
-	accountUpdateTimer = metrics.NewRegisteredTimer("chain/account/updates", nil)
-	accountCommitTimer = metrics.NewRegisteredTimer("chain/account/commits", nil)
-
-	storageReadTimer   = metrics.NewRegisteredTimer("chain/storage/reads", nil)
-	storageHashTimer   = metrics.NewRegisteredTimer("chain/storage/hashes", nil)
-	storageUpdateTimer = metrics.NewRegisteredTimer("chain/storage/updates", nil)
-	storageCommitTimer = metrics.NewRegisteredTimer("chain/storage/commits", nil)
-
-	blockInsertTimer     = metrics.NewRegisteredTimer("chain/inserts", nil)
-	blockValidationTimer = metrics.NewRegisteredTimer("chain/validation", nil)
-	blockExecutionTimer  = metrics.NewRegisteredTimer("chain/execution", nil)
-	blockWriteTimer      = metrics.NewRegisteredTimer("chain/write", nil)
+	accountReadTimer   = metrics.NewRegisteredResettingTimer("chain/account/reads", nil)
+	accountHashTimer   = metrics.NewRegisteredResettingTimer("chain/account/hashes", nil)
+	accountUpdateTimer = metrics.NewRegisteredResettingTimer("chain/account/updates", nil)
+	accountCommitTimer = metrics.NewRegisteredResettingTimer("chain/account/commits", nil)
+
+	storageReadTimer   = metrics.NewRegisteredResettingTimer("chain/storage/reads", nil)
+	storageHashTimer   = metrics.NewRegisteredResettingTimer("chain/storage/hashes", nil)
+	storageUpdateTimer = metrics.NewRegisteredResettingTimer("chain/storage/updates", nil)
+	storageCommitTimer = metrics.NewRegisteredResettingTimer("chain/storage/commits", nil)
+
+	blockInsertTimer     = metrics.NewRegisteredResettingTimer("chain/inserts", nil)
+	blockValidationTimer = metrics.NewRegisteredResettingTimer("chain/validation", nil)
+	blockExecutionTimer  = metrics.NewRegisteredResettingTimer("chain/execution", nil)
+	blockWriteTimer      = metrics.NewRegisteredResettingTimer("chain/write", nil)
 
 	blockReorgMeter     = metrics.NewRegisteredMeter("chain/reorg/executes", nil)
 	blockReorgAddMeter  = metrics.NewRegisteredMeter("chain/reorg/add", nil)

core/state/state_object.go

@@ -26,7 +26,6 @@ import (
 	"github.com/XinFinOrg/XDPoSChain/common"
 	"github.com/XinFinOrg/XDPoSChain/core/types"
 	"github.com/XinFinOrg/XDPoSChain/crypto"
-	"github.com/XinFinOrg/XDPoSChain/metrics"
 	"github.com/XinFinOrg/XDPoSChain/rlp"
 )
 
@@ -176,9 +175,7 @@ func (s *stateObject) GetCommittedState(db Database, key common.Hash) common.Has
 		return s.fakeStorage[key]
 	}
 	// Track the amount of time wasted on reading the storge trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.db.StorageReads += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.db.StorageReads += time.Since(start) }(time.Now())
 	value := common.Hash{}
 	// Load from DB in case it is missing.
 	enc, err := s.getTrie(db).TryGet(key[:])
@@ -276,9 +273,7 @@ func (s *stateObject) setState(key, value common.Hash) {
 // updateTrie writes cached storage modifications into the object's storage trie.
 func (s *stateObject) updateTrie(db Database) Trie {
 	// Track the amount of time wasted on updating the storge trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.db.StorageUpdates += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.db.StorageUpdates += time.Since(start) }(time.Now())
 	tr := s.getTrie(db)
 	for key, value := range s.dirtyStorage {
 		delete(s.dirtyStorage, key)
@@ -298,9 +293,8 @@ func (s *stateObject) updateRoot(db Database) {
 	s.updateTrie(db)
 
 	// Track the amount of time wasted on hashing the storge trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.db.StorageHashes += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.db.StorageHashes += time.Since(start) }(time.Now())
+
 	s.data.Root = s.trie.Hash()
 }
 
@@ -312,9 +306,8 @@ func (s *stateObject) CommitTrie(db Database) error {
 		return s.dbErr
 	}
 	// Track the amount of time wasted on committing the storge trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.db.StorageCommits += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.db.StorageCommits += time.Since(start) }(time.Now())
+
 	root, err := s.trie.Commit(nil)
 	if err == nil {
 		s.data.Root = root

core/state/statedb.go

@@ -28,7 +28,6 @@ import (
 	"github.com/XinFinOrg/XDPoSChain/core/types"
 	"github.com/XinFinOrg/XDPoSChain/crypto"
 	"github.com/XinFinOrg/XDPoSChain/log"
-	"github.com/XinFinOrg/XDPoSChain/metrics"
 	"github.com/XinFinOrg/XDPoSChain/params"
 	"github.com/XinFinOrg/XDPoSChain/rlp"
 	"github.com/XinFinOrg/XDPoSChain/trie"
@@ -459,9 +458,8 @@ func (s *StateDB) GetTransientState(addr common.Address, key common.Hash) common
 // updateStateObject writes the given object to the trie.
 func (s *StateDB) updateStateObject(stateObject *stateObject) {
 	// Track the amount of time wasted on updating the account from the trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now())
+
 	// Encode the account and update the account trie
 	addr := stateObject.Address()
 
@@ -475,9 +473,8 @@ func (s *StateDB) updateStateObject(stateObject *stateObject) {
 // deleteStateObject removes the given object from the state trie.
 func (s *StateDB) deleteStateObject(stateObject *stateObject) {
 	// Track the amount of time wasted on deleting the account from the trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now())
+
 	// Delete the account from the trie
 	stateObject.deleted = true
 
@@ -503,9 +500,8 @@ func (s *StateDB) getStateObject(addr common.Address) (stateObject *stateObject)
 		return obj
 	}
 	// Track the amount of time wasted on loading the object from the database
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.AccountReads += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.AccountReads += time.Since(start) }(time.Now())
+
 	// Load the object from the database
 	enc, err := s.trie.TryGet(addr[:])
 	if len(enc) == 0 {
@@ -701,9 +697,8 @@ func (s *StateDB) IntermediateRoot(deleteEmptyObjects bool) common.Hash {
 	s.Finalise(deleteEmptyObjects)
 
 	// Track the amount of time wasted on hashing the account trie
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.AccountHashes += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.AccountHashes += time.Since(start) }(time.Now())
+
 	return s.trie.Hash()
 }
 
@@ -770,9 +765,8 @@ func (s *StateDB) Commit(deleteEmptyObjects bool) (root common.Hash, err error)
 		delete(s.stateObjectsDirty, addr)
 	}
 	// Write the account trie changes, measuing the amount of wasted time
-	if metrics.EnabledExpensive {
-		defer func(start time.Time) { s.AccountCommits += time.Since(start) }(time.Now())
-	}
+	defer func(start time.Time) { s.AccountCommits += time.Since(start) }(time.Now())
+
 	root, err = s.trie.Commit(func(leaf []byte, parent common.Hash) error {
 		var account Account
 		if err := rlp.DecodeBytes(leaf, &account); err != nil {

metrics/config.go

@@ -19,7 +19,7 @@ package metrics
 // Config contains the configuration for the metric collection.
 type Config struct {
 	Enabled          bool   `toml:",omitempty"`
-	EnabledExpensive bool   `toml:",omitempty"`
+	EnabledExpensive bool   `toml:"-"`
 	HTTP             string `toml:",omitempty"`
 	Port             int    `toml:",omitempty"`
 	EnableInfluxDB   bool   `toml:",omitempty"`

metrics/influxdb/influxdb.go

@@ -98,20 +98,23 @@ func readMeter(namespace, name string, i interface{}) (string, map[string]interf
 		}
 		return measurement, fields
 	case metrics.ResettingTimer:
-		t := metric.Snapshot()
-		if t.Count() == 0 {
+		ms := metric.Snapshot()
+		if ms.Count() == 0 {
 			break
 		}
-		ps := t.Percentiles([]float64{0.50, 0.95, 0.99})
-		measurement := fmt.Sprintf("%s%s.span", namespace, name)
+		ps := ms.Percentiles([]float64{0.5, 0.75, 0.95, 0.99, 0.999, 0.9999})
+		measurement := fmt.Sprintf("%s%s.timer", namespace, name)
 		fields := map[string]interface{}{
-			"count": t.Count(),
-			"max":   t.Max(),
-			"mean":  t.Mean(),
-			"min":   t.Min(),
-			"p50":   int(ps[0]),
-			"p95":   int(ps[1]),
-			"p99":   int(ps[2]),
+			"count": ms.Count(),
+			"max":   ms.Max(),
+			"mean":  ms.Mean(),
+			"min":   ms.Min(),
+			"p50":   ps[0],
+			"p75":   ps[1],
+			"p95":   ps[2],
+			"p99":   ps[3],
+			"p999":  ps[4],
+			"p9999": ps[5],
 		}
 		return measurement, fields
 	}

metrics/influxdb/testdata/influxdbv1.want

@@ -7,5 +7,5 @@ goth.test/gauge_float64.gauge value=34567.89 978307200000000000
 goth.test/gauge_info.gauge value="{\"arch\":\"amd64\",\"commit\":\"7caa2d8163ae3132c1c2d6978c76610caee2d949\",\"os\":\"linux\",\"protocol_versions\":\"64 65 66\",\"version\":\"1.10.18-unstable\"}" 978307200000000000
 goth.test/histogram.histogram count=3i,max=3i,mean=2,min=1i,p25=1,p50=2,p75=3,p95=3,p99=3,p999=3,p9999=3,stddev=0.816496580927726,variance=0.6666666666666666 978307200000000000
 goth.test/meter.meter count=0i,m1=0,m15=0,m5=0,mean=0 978307200000000000
-goth.test/resetting_timer.span count=6i,max=120000000i,mean=30000000,min=10000000i,p50=12500000i,p95=120000000i,p99=120000000i 978307200000000000
+goth.test/resetting_timer.timer count=6i,max=120000000i,mean=30000000,min=10000000i,p50=12500000,p75=40500000,p95=120000000,p99=120000000,p999=120000000,p9999=120000000 978307200000000000
 goth.test/timer.timer count=6i,m1=0,m15=0,m5=0,max=120000000i,mean=38333333.333333336,meanrate=0,min=20000000i,p50=22500000,p75=48000000,p95=120000000,p99=120000000,p999=120000000,p9999=120000000,stddev=36545253.529775314,variance=1335555555555555.2 978307200000000000

metrics/influxdb/testdata/influxdbv2.want

@@ -7,5 +7,5 @@ goth.test/gauge_float64.gauge value=34567.89 978307200000000000
 goth.test/gauge_info.gauge value="{\"arch\":\"amd64\",\"commit\":\"7caa2d8163ae3132c1c2d6978c76610caee2d949\",\"os\":\"linux\",\"protocol_versions\":\"64 65 66\",\"version\":\"1.10.18-unstable\"}" 978307200000000000
 goth.test/histogram.histogram count=3i,max=3i,mean=2,min=1i,p25=1,p50=2,p75=3,p95=3,p99=3,p999=3,p9999=3,stddev=0.816496580927726,variance=0.6666666666666666 978307200000000000
 goth.test/meter.meter count=0i,m1=0,m15=0,m5=0,mean=0 978307200000000000
-goth.test/resetting_timer.span count=6i,max=120000000i,mean=30000000,min=10000000i,p50=12500000i,p95=120000000i,p99=120000000i 978307200000000000
+goth.test/resetting_timer.timer count=6i,max=120000000i,mean=30000000,min=10000000i,p50=12500000,p75=40500000,p95=120000000,p99=120000000,p999=120000000,p9999=120000000 978307200000000000
 goth.test/timer.timer count=6i,m1=0,m15=0,m5=0,max=120000000i,mean=38333333.333333336,meanrate=0,min=20000000i,p50=22500000,p75=48000000,p95=120000000,p99=120000000,p999=120000000,p9999=120000000,stddev=36545253.529775314,variance=1335555555555555.2 978307200000000000

metrics/metrics.go

@@ -24,23 +24,12 @@ import (
 // for less cluttered pprof profiles.
 var Enabled = false
 
-// EnabledExpensive is a soft-flag meant for external packages to check if costly
-// metrics gathering is allowed or not. The goal is to separate standard metrics
-// for health monitoring and debug metrics that might impact runtime performance.
-var EnabledExpensive = false
-
 // enablerFlags is the CLI flag names to use to enable metrics collections.
 var enablerFlags = []string{"metrics"}
 
 // enablerEnvVars is the env var names to use to enable metrics collections.
 var enablerEnvVars = []string{"XDC_METRICS"}
 
-// expensiveEnablerFlags is the CLI flag names to use to enable metrics collections.
-var expensiveEnablerFlags = []string{"metrics-expensive"}
-
-// expensiveEnablerEnvVars is the env var names to use to enable metrics collections.
-var expensiveEnablerEnvVars = []string{"XDC_METRICS_EXPENSIVE"}
-
 // Init enables or disables the metrics system. Since we need this to run before
 // any other code gets to create meters and timers, we'll actually do an ugly hack
 // and peek into the command line args for the metrics flag.
@@ -53,14 +42,6 @@ func init() {
 			}
 		}
 	}
-	for _, enabler := range expensiveEnablerEnvVars {
-		if val, found := syscall.Getenv(enabler); found && !EnabledExpensive {
-			if enable, _ := strconv.ParseBool(val); enable { // ignore error, flag parser will choke on it later
-				log.Info("Enabling expensive metrics collection")
-				EnabledExpensive = true
-			}
-		}
-	}
 	for _, arg := range os.Args {
 		flag := strings.TrimLeft(arg, "-")
 
@@ -70,12 +51,6 @@ func init() {
 				Enabled = true
 			}
 		}
-		for _, enabler := range expensiveEnablerFlags {
-			if !EnabledExpensive && flag == enabler {
-				log.Info("Enabling expensive metrics collection")
-				EnabledExpensive = true
-			}
-		}
 	}
 }
 

metrics/prometheus/collector.go

@@ -125,12 +125,13 @@ func (c *collector) addResettingTimer(name string, m metrics.ResettingTimerSnaps
 	if m.Count() <= 0 {
 		return
 	}
-	ps := m.Percentiles([]float64{0.50, 0.95, 0.99})
+	pv := []float64{0.5, 0.75, 0.95, 0.99, 0.999, 0.9999}
+	ps := m.Percentiles(pv)
 	c.writeSummaryCounter(name, m.Count())
 	c.buff.WriteString(fmt.Sprintf(typeSummaryTpl, mutateKey(name)))
-	c.writeSummaryPercentile(name, "0.50", ps[0])
-	c.writeSummaryPercentile(name, "0.95", ps[1])
-	c.writeSummaryPercentile(name, "0.99", ps[2])
+	for i := range pv {
+		c.writeSummaryPercentile(name, strconv.FormatFloat(pv[i], 'f', -1, 64), ps[i])
+	}
 	c.buff.WriteRune('\n')
 }
 

metrics/prometheus/testdata/prometheus.want

@@ -53,9 +53,12 @@ test_meter 0
 test_resetting_timer_count 6
 
 # TYPE test_resetting_timer summary
-test_resetting_timer {quantile="0.50"} 1.25e+07
+test_resetting_timer {quantile="0.5"} 1.25e+07
+test_resetting_timer {quantile="0.75"} 4.05e+07
 test_resetting_timer {quantile="0.95"} 1.2e+08
 test_resetting_timer {quantile="0.99"} 1.2e+08
+test_resetting_timer {quantile="0.999"} 1.2e+08
+test_resetting_timer {quantile="0.9999"} 1.2e+08
 
 # TYPE test_timer_count counter
 test_timer_count 6