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

* cmd, core, metrics: always report expensive metrics

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

* metrics: update reporter tests
This commit is contained in:
Daniel Liu 2024-12-13 14:00:13 +08:00
parent 6f67b357de
commit 2220156b9a
13 changed files with 62 additions and 91 deletions

View file

@ -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)

View file

@ -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

View file

@ -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.

View file

@ -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)
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.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)
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.NewRegisteredTimer("chain/inserts", nil)
blockValidationTimer = metrics.NewRegisteredTimer("chain/validation", nil)
blockExecutionTimer = metrics.NewRegisteredTimer("chain/execution", nil)
blockWriteTimer = metrics.NewRegisteredTimer("chain/write", 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)

View file

@ -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

View file

@ -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 {

View file

@ -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"`

View file

@ -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
}

View file

@ -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

View file

@ -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

View file

@ -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
}
}
}
}

View file

@ -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')
}

View file

@ -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