From 809e7d539019e815047ff025b7fb9e6cccd8df2d Mon Sep 17 00:00:00 2001 From: vyzo Date: Sat, 8 Aug 2020 16:51:30 +0300 Subject: [PATCH 1/2] add timings to various components of message selection --- chain/messagepool/selection.go | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/chain/messagepool/selection.go b/chain/messagepool/selection.go index 9c4b0d2e1..cb80247f4 100644 --- a/chain/messagepool/selection.go +++ b/chain/messagepool/selection.go @@ -90,6 +90,7 @@ func (mp *MessagePool) selectMessages(curTs, ts *types.TipSet) ([]*types.SignedM // 3. Merge the head chains to produce the list of messages selected for inclusion, subject to // the block gas limit. + startMerge := time.Now() last := len(chains) for i, chain := range chains { // does it fit in the block? @@ -108,6 +109,7 @@ func (mp *MessagePool) selectMessages(curTs, ts *types.TipSet) ([]*types.SignedM last = i break } + log.Infof("merge message chains; took %s", time.Since(startMerge)) // 4. We have reached the edge of what we can fit wholesale; if we still have available gasLimit // to pack some more chains, then trim the last chain and push it down. @@ -115,6 +117,7 @@ func (mp *MessagePool) selectMessages(curTs, ts *types.TipSet) ([]*types.SignedM // dependency cannot be (fully) included. // We do this in a loop because the blocker might have been inordinately large and we might // have to do it multiple times to satisfy tail packing. + startTail := time.Now() tailLoop: for gasLimit >= minGas && last < len(chains) { // trim @@ -157,11 +160,17 @@ tailLoop: // -- mark the end. last = len(chains) } + log.Infof("pack tail chains; took %s", time.Since(startTail)) return result, nil } func (mp *MessagePool) selectPriorityMessages(pending map[address.Address]map[uint64]*types.SignedMessage, baseFee types.BigInt, ts *types.TipSet) ([]*types.SignedMessage, int64) { + start := time.Now() + defer func() { + log.Infof("select priority messages; took %s", time.Since(start)) + }() + result := make([]*types.SignedMessage, 0, mp.cfg.SizeLimitLow) gasLimit := int64(build.BlockGasLimit) minGas := int64(gasguess.MinGas) @@ -242,6 +251,11 @@ tailLoop: } func (mp *MessagePool) getPendingMessages(curTs, ts *types.TipSet) (map[address.Address]map[uint64]*types.SignedMessage, error) { + start := time.Now() + defer func() { + log.Infof("get pending messages; took %s", time.Since(start)) + }() + result := make(map[address.Address]map[uint64]*types.SignedMessage) haveCids := make(map[cid.Cid]struct{}) From b4692770462d65e5f1cd6810c51d13d45f683cd4 Mon Sep 17 00:00:00 2001 From: vyzo Date: Sat, 8 Aug 2020 16:59:08 +0300 Subject: [PATCH 2/2] use structured logging for timings --- chain/messagepool/selection.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/chain/messagepool/selection.go b/chain/messagepool/selection.go index cb80247f4..014bd4ab2 100644 --- a/chain/messagepool/selection.go +++ b/chain/messagepool/selection.go @@ -59,7 +59,7 @@ func (mp *MessagePool) selectMessages(curTs, ts *types.TipSet) ([]*types.SignedM // defer only here so if we have no pending messages we don't spam defer func() { - log.Infof("message selection took %s", time.Since(start)) + log.Infow("message selection done", "took", time.Since(start)) }() // 0b. Select all priority messages that fit in the block @@ -109,7 +109,7 @@ func (mp *MessagePool) selectMessages(curTs, ts *types.TipSet) ([]*types.SignedM last = i break } - log.Infof("merge message chains; took %s", time.Since(startMerge)) + log.Infow("merge message chains done", "took", time.Since(startMerge)) // 4. We have reached the edge of what we can fit wholesale; if we still have available gasLimit // to pack some more chains, then trim the last chain and push it down. @@ -160,7 +160,7 @@ tailLoop: // -- mark the end. last = len(chains) } - log.Infof("pack tail chains; took %s", time.Since(startTail)) + log.Infow("pack tail chains done", "took", time.Since(startTail)) return result, nil } @@ -168,7 +168,7 @@ tailLoop: func (mp *MessagePool) selectPriorityMessages(pending map[address.Address]map[uint64]*types.SignedMessage, baseFee types.BigInt, ts *types.TipSet) ([]*types.SignedMessage, int64) { start := time.Now() defer func() { - log.Infof("select priority messages; took %s", time.Since(start)) + log.Infow("select priority messages done", "took", time.Since(start)) }() result := make([]*types.SignedMessage, 0, mp.cfg.SizeLimitLow) @@ -253,7 +253,7 @@ tailLoop: func (mp *MessagePool) getPendingMessages(curTs, ts *types.TipSet) (map[address.Address]map[uint64]*types.SignedMessage, error) { start := time.Now() defer func() { - log.Infof("get pending messages; took %s", time.Since(start)) + log.Infow("get pending messages done", "took", time.Since(start)) }() result := make(map[address.Address]map[uint64]*types.SignedMessage)