xmaker: add more xmaker metrics and profiles

pkg/exchange/batch/time_range_query.go

@@ -9,7 +9,7 @@ import (
 	"github.com/sirupsen/logrus"
 	"golang.org/x/time/rate"
 
-	"github.com/c9s/bbgo/pkg/util"
+	"github.com/c9s/bbgo/pkg/profile/timeprofile"
 )
 
 var log = logrus.WithField("component", "batch")
@@ -56,7 +56,7 @@ func (q *AsyncTimeRangedBatchQuery) Query(ctx context.Context, ch interface{}, s
 
 			log.Debugf("batch querying %T: %v <=> %v", q.Type, startTime, endTime)
 
-			queryProfiler := util.StartTimeProfile("remoteQuery")
+			queryProfiler := timeprofile.Start("remoteQuery")
 
 			sliceInf, err := q.Q(startTime, endTime)
 			if err != nil {

pkg/profile/timeprofile/timeprofile.go

@@ -1,34 +1,43 @@
-package util
+package timeprofile
 
 import (
 	"time"
 )
 
+type logFunction func(format string, args ...interface{})
+
 type TimeProfile struct {
 	Name               string
 	StartTime, EndTime time.Time
 	Duration           time.Duration
 }
 
-func StartTimeProfile(args ...string) TimeProfile {
+func Start(args ...string) TimeProfile {
 	name := ""
 	if len(args) > 0 {
 		name = args[0]
 	}
+
 	return TimeProfile{StartTime: time.Now(), Name: name}
 }
 
+// TilNow returns the duration from the start time to now
 func (p *TimeProfile) TilNow() time.Duration {
 	return time.Since(p.StartTime)
 }
 
+// Stop stops the time profile, set the end time and returns the duration
 func (p *TimeProfile) Stop() time.Duration {
 	p.EndTime = time.Now()
 	p.Duration = p.EndTime.Sub(p.StartTime)
 	return p.Duration
 }
 
-type logFunction func(format string, args ...interface{})
+// Do runs the function f and stops the time profile
+func (p *TimeProfile) Do(f func()) {
+	defer p.Stop()
+	f()
+}
 
 func (p *TimeProfile) StopAndLog(f logFunction) {
 	duration := p.Stop()

pkg/strategy/tri/strategy.go

@@ -18,10 +18,10 @@ import (
 	"github.com/c9s/bbgo/pkg/core"
 	"github.com/c9s/bbgo/pkg/exchange/retry"
 	"github.com/c9s/bbgo/pkg/fixedpoint"
+	"github.com/c9s/bbgo/pkg/profile/timeprofile"
 	"github.com/c9s/bbgo/pkg/sigchan"
 	"github.com/c9s/bbgo/pkg/style"
 	"github.com/c9s/bbgo/pkg/types"
-	"github.com/c9s/bbgo/pkg/util"
 )
 
 //go:generate bash symbols.sh
@@ -675,7 +675,7 @@ func (s *Strategy) iocOrderExecution(
 }
 
 func (s *Strategy) waitWebSocketOrderDone(ctx context.Context, orderID uint64, timeoutDuration time.Duration) (*types.Order, error) {
-	prof := util.StartTimeProfile("waitWebSocketOrderDone")
+	prof := timeprofile.Start("waitWebSocketOrderDone")
 	defer prof.StopAndLog(log.Infof)
 
 	if order, ok := s.orderStore.Get(orderID); ok {
@@ -869,7 +869,7 @@ func (s *Strategy) calculateRanks(minRatio float64, method func(p *Path) float64
 func waitForOrderFilled(
 	ctx context.Context, ex types.ExchangeOrderQueryService, order types.Order, timeout time.Duration,
 ) (*types.Order, error) {
-	prof := util.StartTimeProfile("waitForOrderFilled")
+	prof := timeprofile.Start("waitForOrderFilled")
 	defer prof.StopAndLog(log.Infof)
 
 	timeoutC := time.After(timeout)
@@ -880,7 +880,7 @@ func waitForOrderFilled(
 			return nil, fmt.Errorf("order wait timeout %s", timeout)
 
 		default:
-			p := util.StartTimeProfile("queryOrder")
+			p := timeprofile.Start("queryOrder")
 			remoteOrder, err2 := ex.QueryOrder(ctx, types.OrderQuery{
 				Symbol:  order.Symbol,
 				OrderID: strconv.FormatUint(order.OrderID, 10),

pkg/strategy/xmaker/metrics.go

@@ -2,6 +2,18 @@ package xmaker
 
 import "github.com/prometheus/client_golang/prometheus"
 
+var cancelOrderDurationMetrics = prometheus.NewHistogramVec(
+	prometheus.HistogramOpts{
+		Name: "xmaker_cancel_order_duration_milliseconds",
+		Help: "cancel order duration in milliseconds",
+	}, []string{"strategy_type", "strategy_id", "exchange", "symbol"})
+
+var makerOrderPlacementDurationMetrics = prometheus.NewHistogramVec(
+	prometheus.HistogramOpts{
+		Name: "xmaker_maker_order_placement_duration_milliseconds",
+		Help: "maker order placement duration in milliseconds",
+	}, []string{"strategy_type", "strategy_id", "exchange", "symbol"})
+
 var openOrderBidExposureInUsdMetrics = prometheus.NewGaugeVec(
 	prometheus.GaugeOpts{
 		Name: "xmaker_open_order_bid_exposure_in_usd",
@@ -77,6 +89,8 @@ func init() {
 		bidMarginMetrics,
 		askMarginMetrics,
 		aggregatedSignalMetrics,
+		cancelOrderDurationMetrics,
+		makerOrderPlacementDurationMetrics,
 		configNumOfLayersMetrics,
 		configMaxExposureMetrics,
 		configBidMarginMetrics,

pkg/strategy/xmaker/strategy.go

@@ -17,6 +17,7 @@ import (
 	"github.com/c9s/bbgo/pkg/fixedpoint"
 	indicatorv2 "github.com/c9s/bbgo/pkg/indicator/v2"
 	"github.com/c9s/bbgo/pkg/pricesolver"
+	"github.com/c9s/bbgo/pkg/profile/timeprofile"
 	"github.com/c9s/bbgo/pkg/risk/circuitbreaker"
 	"github.com/c9s/bbgo/pkg/strategy/common"
 	"github.com/c9s/bbgo/pkg/types"
@@ -914,12 +915,15 @@ func (s *Strategy) updateQuote(ctx context.Context) error {
 
 	defer s.tradeCollector.Process()
 
+	makerOrderPlacementProfile := timeprofile.Start("makerOrderPlacement")
 	createdOrders, errIdx, err := bbgo.BatchPlaceOrder(ctx, s.makerSession.Exchange, s.makerOrderCreateCallback, formattedOrders...)
 	if err != nil {
 		log.WithError(err).Errorf("unable to place maker orders: %+v", formattedOrders)
 		return err
 	}
 
+	makerOrderPlacementDurationMetrics.With(s.metricsLabels).Observe(float64(makerOrderPlacementProfile.Stop().Milliseconds()))
+
 	openOrderBidExposureInUsdMetrics.With(s.metricsLabels).Set(bidExposureInUsd.Float64())
 	openOrderAskExposureInUsdMetrics.With(s.metricsLabels).Set(askExposureInUsd.Float64())