Merge pull request hyperledger-labs#107 from dongrie/time-track

Add time track

core/channel.go

@@ -15,6 +15,7 @@ import (
 // TODO: add max retries or something to this function
 func CreateChannel(src, dst *ProvableChain, ordered bool, to time.Duration) error {
 	logger := GetChannelPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "CreateChannel")
 	var order chantypes.Order
 	if ordered {
 		order = chantypes.ORDERED

core/client.go

@@ -1,13 +1,16 @@
 package core
 
 import (
+	"time"
+
 	sdk "github.com/cosmos/cosmos-sdk/types"
 	"github.com/hyperledger-labs/yui-relayer/log"
 	"golang.org/x/sync/errgroup"
 )
 
 func CreateClients(src, dst *ProvableChain) error {
 	logger := GetChainPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "CreateClients")
 	var (
 		clients = &RelayMsgs{Src: []sdk.Msg{}, Dst: []sdk.Msg{}}
 	)
@@ -76,6 +79,7 @@ func CreateClients(src, dst *ProvableChain) error {
 
 func UpdateClients(src, dst *ProvableChain) error {
 	logger := GetClientPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "UpdateClients")
 	var (
 		clients = &RelayMsgs{Src: []sdk.Msg{}, Dst: []sdk.Msg{}}
 	)

core/connection.go

@@ -24,6 +24,7 @@ var (
 
 func CreateConnection(src, dst *ProvableChain, to time.Duration) error {
 	logger := GetConnectionPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "CreateConnection")
 	ticker := time.NewTicker(to)
 
 	failed := 0

core/naive-strategy.go

@@ -3,6 +3,7 @@ package core
 import (
 	"context"
 	"fmt"
+	"time"
 
 	retry "github.com/avast/retry-go"
 	sdk "github.com/cosmos/cosmos-sdk/types"
@@ -72,6 +73,7 @@ func getQueryContext(chain *ProvableChain, sh SyncHeaders, useFinalizedHeader bo
 
 func (st *NaiveStrategy) UnrelayedPackets(src, dst *ProvableChain, sh SyncHeaders, includeRelayedButUnfinalized bool) (*RelayPackets, error) {
 	logger := GetChannelPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "UnrelayedPackets")
 	var (
 		eg         = new(errgroup.Group)
 		srcPackets PacketInfoList
@@ -177,6 +179,7 @@ func (st *NaiveStrategy) UnrelayedPackets(src, dst *ProvableChain, sh SyncHeader
 
 func (st *NaiveStrategy) RelayPackets(src, dst *ProvableChain, rp *RelayPackets, sh SyncHeaders) error {
 	logger := GetChannelPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "RelayPackets")
 	// set the maximum relay transaction constraints
 	msgs := &RelayMsgs{
 		Src:          []sdk.Msg{},
@@ -275,6 +278,7 @@ func (st *NaiveStrategy) RelayPackets(src, dst *ProvableChain, rp *RelayPackets,
 
 func (st *NaiveStrategy) UnrelayedAcknowledgements(src, dst *ProvableChain, sh SyncHeaders, includeRelayedButUnfinalized bool) (*RelayPackets, error) {
 	logger := GetChannelPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "UnrelayedAcknowledgements")
 	var (
 		eg      = new(errgroup.Group)
 		srcAcks PacketInfoList
@@ -417,6 +421,7 @@ func logPacketsRelayed(src, dst Chain, num int, obj string, dir string) {
 
 func (st *NaiveStrategy) RelayAcknowledgements(src, dst *ProvableChain, rp *RelayPackets, sh SyncHeaders) error {
 	logger := GetChannelPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "RelayAcknowledgements")
 	// set the maximum relay transaction constraints
 	msgs := &RelayMsgs{
 		Src:          []sdk.Msg{},

core/packet-tx.go

@@ -9,6 +9,7 @@ import (
 
 func SendTransferMsg(src, dst *ProvableChain, amount sdk.Coin, dstAddr fmt.Stringer, toHeightOffset uint64, toTimeOffset time.Duration) error {
 	logger := GetChannelPairLogger(src, dst)
+	defer logger.TimeTrack(time.Now(), "SendTransferMsg")
 	var (
 		timeoutHeight    uint64
 		timeoutTimestamp uint64

log/slog.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"time"
 
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/errors/withstack"
@@ -80,6 +81,16 @@ func GetLogger() *RelayLogger {
 	return relayLogger
 }
 
+func (rl *RelayLogger) WithChain(
+	chainID string,
+) *RelayLogger {
+	return &RelayLogger{
+		rl.Logger.With(
+			"chain_id", chainID,
+		),
+	}
+}
+
 func (rl *RelayLogger) WithChainPair(
 	srcChainID string,
 	dstChainID string,
@@ -175,3 +186,8 @@ func (rl *RelayLogger) WithModule(
 		),
 	}
 }
+
+func (rl *RelayLogger) TimeTrack(start time.Time, name string) {
+	elapsed := time.Since(start)
+	rl.Logger.Info("time track", "name", name, "elapsed", elapsed.Nanoseconds())
+}