From 5510b761d5d9d3c797b276560a4f98a0dcc3947b Mon Sep 17 00:00:00 2001 From: zsfelfoldi Date: Thu, 5 Sep 2019 02:47:43 +0200 Subject: [PATCH 01/10] les: detailed relative cost metrics --- les/costtracker.go | 25 +++++++++++++++++++++++-- les/metrics.go | 18 +++++++++++++----- 2 files changed, 36 insertions(+), 7 deletions(-) diff --git a/les/costtracker.go b/les/costtracker.go index d1f5b54ca5d0..95faf21d0dac 100644 --- a/les/costtracker.go +++ b/les/costtracker.go @@ -226,6 +226,7 @@ type reqInfo struct { // servingTime is the CPU time corresponding to the actual processing of // the request. servingTime float64 + msgCode uint64 } // gfLoop starts an event loop which updates the global cost factor which is @@ -273,7 +274,27 @@ func (ct *costTracker) gfLoop() { requestServedTimer.Update(time.Duration(r.servingTime)) requestEstimatedMeter.Mark(int64(r.avgTimeCost / factor)) requestEstimatedTimer.Update(time.Duration(r.avgTimeCost / factor)) - relativeCostHistogram.Update(int64(r.avgTimeCost / factor / r.servingTime)) + + relCost := int64(factor * r.servingTime * 10000 / r.avgTimeCost) + relativeCostHistogram.Update(relCost) + switch r.msgCode { + case GetBlockHeadersMsg: + relativeCostHeaderHistogram.Update(relCost) + case GetBlockBodiesMsg: + relativeCostBodyHistogram.Update(relCost) + case GetReceiptsMsg: + relativeCostReceiptHistogram.Update(relCost) + case GetCodeMsg: + relativeCostCodeHistogram.Update(relCost) + case GetProofsV2Msg: + relativeCostProofHistogram.Update(relCost) + case GetHelperTrieProofsMsg: + relativeCostHelperProofHistogram.Update(relCost) + case SendTxV2Msg: + relativeCostSendTxHistogram.Update(relCost) + case GetTxStatusMsg: + relativeCostTxStatusHistogram.Update(relCost) + } now := mclock.Now() dt := float64(now - expUpdate) @@ -375,7 +396,7 @@ func (ct *costTracker) updateStats(code, amount, servingTime, realCost uint64) { avg := reqAvgTimeCost[code] avgTimeCost := avg.baseCost + amount*avg.reqCost select { - case ct.reqInfoCh <- reqInfo{float64(avgTimeCost), float64(servingTime)}: + case ct.reqInfoCh <- reqInfo{float64(avgTimeCost), float64(servingTime), code}: default: } if makeCostStats { diff --git a/les/metrics.go b/les/metrics.go index 797631b8ef7d..aebbdede51d9 100644 --- a/les/metrics.go +++ b/les/metrics.go @@ -69,11 +69,19 @@ var ( totalConnectedGauge = metrics.NewRegisteredGauge("les/server/totalConnected", nil) blockProcessingTimer = metrics.NewRegisteredTimer("les/server/blockProcessingTime", nil) - requestServedMeter = metrics.NewRegisteredMeter("les/server/req/avgServedTime", nil) - requestServedTimer = metrics.NewRegisteredTimer("les/server/req/servedTime", nil) - requestEstimatedMeter = metrics.NewRegisteredMeter("les/server/req/avgEstimatedTime", nil) - requestEstimatedTimer = metrics.NewRegisteredTimer("les/server/req/estimatedTime", nil) - relativeCostHistogram = metrics.NewRegisteredHistogram("les/server/req/relative", nil, metrics.NewExpDecaySample(1028, 0.015)) + requestServedMeter = metrics.NewRegisteredMeter("les/server/req/avgServedTime", nil) + requestServedTimer = metrics.NewRegisteredTimer("les/server/req/servedTime", nil) + requestEstimatedMeter = metrics.NewRegisteredMeter("les/server/req/avgEstimatedTime", nil) + requestEstimatedTimer = metrics.NewRegisteredTimer("les/server/req/estimatedTime", nil) + relativeCostHistogram = metrics.NewRegisteredHistogram("les/server/req/relative", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostHeaderHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/header", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostBodyHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/body", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostReceiptHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/receipt", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostCodeHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/code", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostProofHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/proof", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostHelperProofHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/helperproof", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostSendTxHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/sendtx", nil, metrics.NewExpDecaySample(1028, 0.015)) + relativeCostTxStatusHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/txstatus", nil, metrics.NewExpDecaySample(1028, 0.015)) recentServedGauge = metrics.NewRegisteredGauge("les/server/recentRequestServed", nil) recentEstimatedGauge = metrics.NewRegisteredGauge("les/server/recentRequestEstimated", nil) From e331baa7cc170e03269d3b13f48c056d96c9dbc3 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Wed, 11 Sep 2019 19:58:03 +0800 Subject: [PATCH 02/10] les: filter txpool relative request statistic --- les/costtracker.go | 59 +++++++++++++++++++++++++++---------------- les/server_handler.go | 17 ++++++++----- 2 files changed, 47 insertions(+), 29 deletions(-) diff --git a/les/costtracker.go b/les/costtracker.go index 95faf21d0dac..7b169f31b53f 100644 --- a/les/costtracker.go +++ b/les/costtracker.go @@ -28,6 +28,7 @@ import ( "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/les/flowcontrol" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" ) const makeCostStats = false // make request cost statistics during operation @@ -87,7 +88,7 @@ const ( gfUsageTC = time.Second gfRaiseTC = time.Second * 200 gfDropTC = time.Second * 50 - gfDbKey = "_globalCostFactorV3" + gfDbKey = "_globalCostFactorV4" ) // costTracker is responsible for calculating costs and cost estimates on the @@ -226,7 +227,9 @@ type reqInfo struct { // servingTime is the CPU time corresponding to the actual processing of // the request. servingTime float64 - msgCode uint64 + + // msgCode indicates the type of request. + msgCode uint64 } // gfLoop starts an event loop which updates the global cost factor which is @@ -270,31 +273,43 @@ func (ct *costTracker) gfLoop() { for { select { case r := <-ct.reqInfoCh: + relCost := int64(factor * r.servingTime * 100 / r.avgTimeCost) // Convert the value to a percentage form + + // Record more metrics if we are debugging + if metrics.EnabledExpensive { + switch r.msgCode { + case GetBlockHeadersMsg: + relativeCostHeaderHistogram.Update(relCost) + case GetBlockBodiesMsg: + relativeCostBodyHistogram.Update(relCost) + case GetReceiptsMsg: + relativeCostReceiptHistogram.Update(relCost) + case GetCodeMsg: + relativeCostCodeHistogram.Update(relCost) + case GetProofsV2Msg: + relativeCostProofHistogram.Update(relCost) + case GetHelperTrieProofsMsg: + relativeCostHelperProofHistogram.Update(relCost) + case SendTxV2Msg: + relativeCostSendTxHistogram.Update(relCost) + case GetTxStatusMsg: + relativeCostTxStatusHistogram.Update(relCost) + } + } + // SendTxV2 and GetTxStatus requests are two special cases. + // All other requests will only put pressure on the database, and + // the corresponding delay is relatively stable. While these two + // requests involve txpool query, which is usually unstable. + // + // TODO(rjl493456442) fixes this. + if r.msgCode == SendTxV2Msg || r.msgCode == GetTxStatusMsg { + continue + } requestServedMeter.Mark(int64(r.servingTime)) requestServedTimer.Update(time.Duration(r.servingTime)) requestEstimatedMeter.Mark(int64(r.avgTimeCost / factor)) requestEstimatedTimer.Update(time.Duration(r.avgTimeCost / factor)) - - relCost := int64(factor * r.servingTime * 10000 / r.avgTimeCost) relativeCostHistogram.Update(relCost) - switch r.msgCode { - case GetBlockHeadersMsg: - relativeCostHeaderHistogram.Update(relCost) - case GetBlockBodiesMsg: - relativeCostBodyHistogram.Update(relCost) - case GetReceiptsMsg: - relativeCostReceiptHistogram.Update(relCost) - case GetCodeMsg: - relativeCostCodeHistogram.Update(relCost) - case GetProofsV2Msg: - relativeCostProofHistogram.Update(relCost) - case GetHelperTrieProofsMsg: - relativeCostHelperProofHistogram.Update(relCost) - case SendTxV2Msg: - relativeCostSendTxHistogram.Update(relCost) - case GetTxStatusMsg: - relativeCostTxStatusHistogram.Update(relCost) - } now := mclock.Now() dt := float64(now - expUpdate) diff --git a/les/server_handler.go b/les/server_handler.go index 79c0a08a91f6..5806647e2a93 100644 --- a/les/server_handler.go +++ b/les/server_handler.go @@ -867,16 +867,19 @@ func (h *serverHandler) getAuxiliaryHeaders(req HelperTrieReq) []byte { // txStatus returns the status of a specified transaction. func (h *serverHandler) txStatus(hash common.Hash) light.TxStatus { var stat light.TxStatus - // Looking the transaction in txpool first. stat.Status = h.txpool.Status([]common.Hash{hash})[0] - // If the transaction is unknown to the pool, try looking it up locally. + // Looking the transaction in database first. + // The reason here is usually txpool has a high pressure in the mainnet, + // the cost to query the status in pool is even higher than database. + lookup := h.blockchain.GetTransactionLookup(hash) + if lookup != nil { + stat.Status = core.TxStatusIncluded + stat.Lookup = lookup + } + // If the transaction is unknown to the database, try looking it up in txpool. if stat.Status == core.TxStatusUnknown { - lookup := h.blockchain.GetTransactionLookup(hash) - if lookup != nil { - stat.Status = core.TxStatusIncluded - stat.Lookup = lookup - } + stat.Status = h.txpool.Status([]common.Hash{hash})[0] } return stat } From 5bdd98b6744ba34bd3b74757d9c224bbf477af8c Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Thu, 12 Sep 2019 14:51:56 +0200 Subject: [PATCH 03/10] les: quick and dirty workaround for mclock leaps --- les/costtracker.go | 20 +++++++++++++++++++- les/metrics.go | 2 ++ 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/les/costtracker.go b/les/costtracker.go index 7b169f31b53f..0daa9ba4493d 100644 --- a/les/costtracker.go +++ b/les/costtracker.go @@ -269,10 +269,29 @@ func (ct *costTracker) gfLoop() { log.Debug("global cost factor saved", "value", factor) } saveTicker := time.NewTicker(time.Minute * 10) + mclockTicker := time.NewTicker(time.Millisecond * 100) + lastClock := mclock.Now() + noUpdate := lastClock for { select { + case <-mclockTicker.C: + now := mclock.Now() + dt := time.Duration(now - lastClock) + lastClock = now + mclockTimer.Update(dt) + if dt > time.Millisecond*300 { + noUpdate = now + mclock.AbsTime(time.Second*5) + } + case r := <-ct.reqInfoCh: + now := mclock.Now() + if time.Duration(now-lastClock) > time.Millisecond*300 { + noUpdate = now + mclock.AbsTime(time.Second*5) + } + if now < noUpdate { + continue + } relCost := int64(factor * r.servingTime * 100 / r.avgTimeCost) // Convert the value to a percentage form // Record more metrics if we are debugging @@ -311,7 +330,6 @@ func (ct *costTracker) gfLoop() { requestEstimatedTimer.Update(time.Duration(r.avgTimeCost / factor)) relativeCostHistogram.Update(relCost) - now := mclock.Now() dt := float64(now - expUpdate) expUpdate = now exp := math.Exp(-dt / float64(gfUsageTC)) diff --git a/les/metrics.go b/les/metrics.go index aebbdede51d9..007c3b54bc79 100644 --- a/les/metrics.go +++ b/les/metrics.go @@ -83,6 +83,8 @@ var ( relativeCostSendTxHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/sendtx", nil, metrics.NewExpDecaySample(1028, 0.015)) relativeCostTxStatusHistogram = metrics.NewRegisteredHistogram("les/server/req/relative/txstatus", nil, metrics.NewExpDecaySample(1028, 0.015)) + mclockTimer = metrics.NewRegisteredTimer("les/server/mclock", nil) + recentServedGauge = metrics.NewRegisteredGauge("les/server/recentRequestServed", nil) recentEstimatedGauge = metrics.NewRegisteredGauge("les/server/recentRequestEstimated", nil) sqServedGauge = metrics.NewRegisteredGauge("les/server/servingQueue/served", nil) From 47a93d5a45f115580b1109f889a3b5cbe4bd57c6 Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Thu, 12 Sep 2019 15:48:53 +0200 Subject: [PATCH 04/10] les: bump global factor db key --- les/costtracker.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/les/costtracker.go b/les/costtracker.go index 0daa9ba4493d..c976a10f6e92 100644 --- a/les/costtracker.go +++ b/les/costtracker.go @@ -88,7 +88,7 @@ const ( gfUsageTC = time.Second gfRaiseTC = time.Second * 200 gfDropTC = time.Second * 50 - gfDbKey = "_globalCostFactorV4" + gfDbKey = "_globalCostFactorV5" ) // costTracker is responsible for calculating costs and cost estimates on the From 88e4a9f9bd3483e71a621125ef9f6bbc98aa0f2c Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Fri, 13 Sep 2019 15:46:28 +0200 Subject: [PATCH 05/10] les: initialize price factors --- les/server.go | 1 + 1 file changed, 1 insertion(+) diff --git a/les/server.go b/les/server.go index 8e790323f6d7..592858cb91e4 100644 --- a/les/server.go +++ b/les/server.go @@ -113,6 +113,7 @@ func NewLesServer(e *eth.Ethereum, config *eth.Config) (*LesServer, error) { } srv.fcManager.SetCapacityLimits(srv.freeCapacity, maxCapacity, srv.freeCapacity*2) srv.clientPool = newClientPool(srv.chainDb, srv.freeCapacity, 10000, mclock.System{}, func(id enode.ID) { go srv.peers.Unregister(peerIdToString(id)) }) + srv.clientPool.setPriceFactors(priceFactors{0, 1, 1}, priceFactors{0, 1, 1}) checkpoint := srv.latestLocalCheckpoint() if !checkpoint.Empty() { From c5d958e205ee93b36fd29fd681b5ff92ea5f0ff5 Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Fri, 13 Sep 2019 15:58:20 +0200 Subject: [PATCH 06/10] les: increased connected bias to lower churn rate --- les/clientpool.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/les/clientpool.go b/les/clientpool.go index cff5f41edd5a..b16c7202ae85 100644 --- a/les/clientpool.go +++ b/les/clientpool.go @@ -33,7 +33,7 @@ import ( const ( negBalanceExpTC = time.Hour // time constant for exponentially reducing negative balance fixedPointMultiplier = 0x1000000 // constant to convert logarithms to fixed point format - connectedBias = time.Minute // this bias is applied in favor of already connected clients in order to avoid kicking them out very soon + connectedBias = time.Minute * 5 // this bias is applied in favor of already connected clients in order to avoid kicking them out very soon lazyQueueRefresh = time.Second * 10 // refresh period of the connected queue ) From e5163d1e050ec80ded49c6f8ff2360591b89ef23 Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Sat, 14 Sep 2019 03:28:59 +0200 Subject: [PATCH 07/10] les: fixed clientPool.setLimits --- les/clientpool.go | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/les/clientpool.go b/les/clientpool.go index b16c7202ae85..6773aab551f8 100644 --- a/les/clientpool.go +++ b/les/clientpool.go @@ -366,12 +366,14 @@ func (f *clientPool) setLimits(count int, totalCap uint64) { f.countLimit = count f.capacityLimit = totalCap - now := mclock.Now() - f.connectedQueue.MultiPop(func(data interface{}, priority int64) bool { - c := data.(*clientInfo) - f.dropClient(c, now, true) - return f.connectedCapacity > f.capacityLimit || f.connectedQueue.Size() > f.countLimit - }) + if f.connectedCapacity > f.capacityLimit || f.connectedQueue.Size() > f.countLimit { + now := mclock.Now() + f.connectedQueue.MultiPop(func(data interface{}, priority int64) bool { + c := data.(*clientInfo) + f.dropClient(c, now, true) + return f.connectedCapacity > f.capacityLimit || f.connectedQueue.Size() > f.countLimit + }) + } } // requestCost feeds request cost after serving a request from the given peer. From 06ee8ab699e0388f8da444f380083f29e8f547e4 Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Sat, 14 Sep 2019 04:17:11 +0200 Subject: [PATCH 08/10] core: do not use mutex in GetAncestor --- core/blockchain.go | 3 --- core/headerchain.go | 7 +++++-- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/core/blockchain.go b/core/blockchain.go index 833de3bc7e69..1bf31b2399d1 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -2151,9 +2151,6 @@ func (bc *BlockChain) GetBlockHashesFromHash(hash common.Hash, max uint64) []com // // Note: ancestor == 0 returns the same block, 1 returns its parent and so on. func (bc *BlockChain) GetAncestor(hash common.Hash, number, ancestor uint64, maxNonCanonical *uint64) (common.Hash, uint64) { - bc.chainmu.RLock() - defer bc.chainmu.RUnlock() - return bc.hc.GetAncestor(hash, number, ancestor, maxNonCanonical) } diff --git a/core/headerchain.go b/core/headerchain.go index 034858f651cf..a2faa3303ae0 100644 --- a/core/headerchain.go +++ b/core/headerchain.go @@ -349,8 +349,11 @@ func (hc *HeaderChain) GetAncestor(hash common.Hash, number, ancestor uint64, ma } for ancestor != 0 { if rawdb.ReadCanonicalHash(hc.chainDb, number) == hash { - number -= ancestor - return rawdb.ReadCanonicalHash(hc.chainDb, number), number + ancestorHash := rawdb.ReadCanonicalHash(hc.chainDb, number-ancestor) + if rawdb.ReadCanonicalHash(hc.chainDb, number) == hash { + number -= ancestor + return ancestorHash, number + } } if *maxNonCanonical == 0 { return common.Hash{}, 0 From 850001135d84002c3b3be0b589267aaaa3108293 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Mon, 16 Sep 2019 15:04:56 +0800 Subject: [PATCH 09/10] les: bump factor db version again --- les/costtracker.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/les/costtracker.go b/les/costtracker.go index c976a10f6e92..7a6a4f9d44cc 100644 --- a/les/costtracker.go +++ b/les/costtracker.go @@ -88,7 +88,7 @@ const ( gfUsageTC = time.Second gfRaiseTC = time.Second * 200 gfDropTC = time.Second * 50 - gfDbKey = "_globalCostFactorV5" + gfDbKey = "_globalCostFactorV6" ) // costTracker is responsible for calculating costs and cost estimates on the From b8f08acbf869363e3309edbb94cee7c8e1b6bf13 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Mon, 16 Sep 2019 17:16:06 +0800 Subject: [PATCH 10/10] les: add metrics --- les/metrics.go | 9 +++++++++ les/server_handler.go | 8 ++++++++ 2 files changed, 17 insertions(+) diff --git a/les/metrics.go b/les/metrics.go index 007c3b54bc79..f439753aedc5 100644 --- a/les/metrics.go +++ b/les/metrics.go @@ -60,6 +60,15 @@ var ( miscOutTxStatusPacketsMeter = metrics.NewRegisteredMeter("les/misc/out/packets/txStatus", nil) miscOutTxStatusTrafficMeter = metrics.NewRegisteredMeter("les/misc/out/traffic/txStatus", nil) + miscServingTimeHeaderTimer = metrics.NewRegisteredTimer("les/misc/serve/header", nil) + miscServingTimeBodyTimer = metrics.NewRegisteredTimer("les/misc/serve/body", nil) + miscServingTimeCodeTimer = metrics.NewRegisteredTimer("les/misc/serve/code", nil) + miscServingTimeReceiptTimer = metrics.NewRegisteredTimer("les/misc/serve/receipt", nil) + miscServingTimeTrieProofTimer = metrics.NewRegisteredTimer("les/misc/serve/proof", nil) + miscServingTimeHelperTrieTimer = metrics.NewRegisteredTimer("les/misc/serve/helperTrie", nil) + miscServingTimeTxTimer = metrics.NewRegisteredTimer("les/misc/serve/tx", nil) + miscServingTimeTxStatusTimer = metrics.NewRegisteredTimer("les/misc/serve/txstatus", nil) + connectionTimer = metrics.NewRegisteredTimer("les/connection/duration", nil) serverConnectionGauge = metrics.NewRegisteredGauge("les/connection/server", nil) clientConnectionGauge = metrics.NewRegisteredGauge("les/connection/client", nil) diff --git a/les/server_handler.go b/les/server_handler.go index 5806647e2a93..b8021850a530 100644 --- a/les/server_handler.go +++ b/les/server_handler.go @@ -268,6 +268,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInHeaderPacketsMeter.Mark(1) miscInHeaderTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeHeaderTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -380,6 +381,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInBodyPacketsMeter.Mark(1) miscInBodyTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeBodyTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -428,6 +430,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInCodePacketsMeter.Mark(1) miscInCodeTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeCodeTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -499,6 +502,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInReceiptPacketsMeter.Mark(1) miscInReceiptTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeReceiptTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -555,6 +559,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInTrieProofPacketsMeter.Mark(1) miscInTrieProofTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeTrieProofTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -657,6 +662,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInHelperTriePacketsMeter.Mark(1) miscInHelperTrieTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeHelperTrieTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -731,6 +737,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInTxsPacketsMeter.Mark(1) miscInTxsTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeTxTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64 @@ -779,6 +786,7 @@ func (h *serverHandler) handleMsg(p *peer, wg *sync.WaitGroup) error { if metrics.EnabledExpensive { miscInTxStatusPacketsMeter.Mark(1) miscInTxStatusTrafficMeter.Mark(int64(msg.Size)) + defer func(start time.Time) { miscServingTimeTxStatusTimer.UpdateSince(start) }(time.Now()) } var req struct { ReqID uint64