diff --git a/pkg/exchange/batch/time_range_query.go b/pkg/exchange/batch/time_range_query.go index 7b8490c59..b2259f8b3 100644 --- a/pkg/exchange/batch/time_range_query.go +++ b/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 { diff --git a/pkg/util/profile.go b/pkg/profile/timeprofile/timeprofile.go similarity index 69% rename from pkg/util/profile.go rename to pkg/profile/timeprofile/timeprofile.go index 1d3753aa2..0a76cc12e 100644 --- a/pkg/util/profile.go +++ b/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() diff --git a/pkg/strategy/tri/strategy.go b/pkg/strategy/tri/strategy.go index 429d9e480..b2d80f711 100644 --- a/pkg/strategy/tri/strategy.go +++ b/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), diff --git a/pkg/strategy/xmaker/metrics.go b/pkg/strategy/xmaker/metrics.go index adedf59f6..144972d65 100644 --- a/pkg/strategy/xmaker/metrics.go +++ b/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, diff --git a/pkg/strategy/xmaker/strategy.go b/pkg/strategy/xmaker/strategy.go index 3036d760c..c48a9e313 100644 --- a/pkg/strategy/xmaker/strategy.go +++ b/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())