log time elapsed

plugin/evm/order_api.go

@@ -7,7 +7,9 @@ import (
 	"context"
 	"encoding/hex"
 	"encoding/json"
+	"log"
 	"strings"
+	"time"
 
 	"github.com/ava-labs/subnet-evm/plugin/evm/orderbook"
 	hu "github.com/ava-labs/subnet-evm/plugin/evm/orderbook/hubbleutils"
@@ -37,8 +39,13 @@ type PlaceSignedOrdersResponse struct {
 
 func (api *OrderAPI) PlaceSignedOrders(ctx context.Context, input string) (PlaceSignedOrdersResponse, error) {
 	// input is a json encoded array of signed orders
+	startTime := time.Now()
+	timeTracker := startTime
+
 	var rawOrders []string
 	err := json.Unmarshal([]byte(input), &rawOrders)
+	timeTracker = hu.LogTimeTaken("step 1", timeTracker)
+	// log.Printf("pos %s", timeTracker)
 	if err != nil {
 		return PlaceSignedOrdersResponse{}, err
 	}
@@ -48,19 +55,24 @@ func (api *OrderAPI) PlaceSignedOrders(ctx context.Context, input string) (Place
 	for _, rawOrder := range rawOrders {
 		orderResponse := PlaceOrderResponse{Success: false}
 		testData, err := hex.DecodeString(strings.TrimPrefix(rawOrder, "0x"))
+		timeTracker = hu.LogTimeTaken("step 2", timeTracker)
+		// log.Printf("pos %s", timeTracker)
 		if err != nil {
 			orderResponse.Error = err.Error()
 			response = append(response, orderResponse)
 			continue
 		}
 		order, err := hu.DecodeSignedOrder(testData)
+		timeTracker = hu.LogTimeTaken("step 3", timeTracker)
+		// log.Printf("pos %s", timeTracker)
 		if err != nil {
 			orderResponse.Error = err.Error()
 			response = append(response, orderResponse)
 			continue
 		}
-
 		orderId, err := api.tradingAPI.PlaceOrder(order)
+		timeTracker = hu.LogTimeTaken("step 4", timeTracker)
+		// log.Printf("pos %s", timeTracker)
 		orderResponse.OrderId = orderId.String()
 		if err != nil {
 			orderResponse.Error = err.Error()
@@ -70,9 +82,12 @@ func (api *OrderAPI) PlaceSignedOrders(ctx context.Context, input string) (Place
 		orderResponse.Success = true
 		response = append(response, orderResponse)
 		ordersToGossip = append(ordersToGossip, order)
+		timeTracker = hu.LogTimeTaken("step 5", timeTracker)
+		// log.Printf("pos %s", timeTracker)
 	}
-
 	api.vm.gossiper.GossipSignedOrders(ordersToGossip)
-
+	timeTracker = hu.LogTimeTaken("step 6", timeTracker)
+	// log.Printf("pos %s", timeTracker)
+	log.Printf("startTime %s, timeTracker %s, elapsed %s", startTime, timeTracker, time.Since(startTime))
 	return PlaceSignedOrdersResponse{Orders: response}, nil
 }

plugin/evm/orderbook/hubbleutils/margin_math.go

@@ -1,8 +1,10 @@
 package hubbleutils
 
 import (
+	"log"
 	"math"
 	"math/big"
+	"time"
 )
 
 type UpgradeVersion uint8
@@ -159,3 +161,12 @@ func GetRequiredMargin(price, fillAmount, minAllowableMargin, takerFee *big.Int)
 	quoteAsset := Div1e18(Mul(fillAmount, price))
 	return Add(Div1e6(Mul(quoteAsset, minAllowableMargin)), Div1e6(Mul(quoteAsset, takerFee)))
 }
+
+func LogTimeTaken(step string, prevTime time.Time) time.Time {
+	now := time.Now()
+	// log.Printf("now %s", now)
+	elapsed := now.Sub(prevTime)
+	// log.Printf("pre %s", prevTime)
+	log.Printf("%s took %s", step, elapsed)
+	return now
+}

plugin/evm/orderbook/trading_apis.go

@@ -314,11 +314,19 @@ func (api *TradingAPI) StreamMarketTrades(ctx context.Context, market Market, bl
 
 // @todo cache api.configService values to avoid db lookups on every order placement
 func (api *TradingAPI) PlaceOrder(order *hu.SignedOrder) (common.Hash, error) {
+	timeTracker := time.Now()
+	if hu.ChainId == 0 { // set once, will need to restart node if we change
+		hu.SetChainIdAndVerifyingSignedOrdersContract(api.backend.ChainConfig().ChainID.Int64(), api.configService.GetSignedOrderbookContract().String())
+	}
+	timeTracker = hu.LogTimeTaken("step 3.1", timeTracker)
+
 	orderId, err := order.Hash()
+	timeTracker = hu.LogTimeTaken("step 3.2", timeTracker)
 	if err != nil {
 		return common.Hash{}, fmt.Errorf("failed to hash order: %s", err)
 	}
 	fields := api.db.GetOrderValidationFields(orderId, order)
+	timeTracker = hu.LogTimeTaken("step 3.3", timeTracker)
 	// P1. Order is not already in memdb
 	if fields.Exists {
 		return orderId, hu.ErrOrderAlreadyExists
@@ -335,19 +343,23 @@ func (api *TradingAPI) PlaceOrder(order *hu.SignedOrder) (common.Hash, error) {
 			Status:             api.configService.GetSignedOrderStatus(orderId),
 		},
 	)
+	timeTracker = hu.LogTimeTaken("step 3.4", timeTracker)
 	if err != nil {
 		return orderId, err
 	}
 	if trader != signer && !api.configService.IsTradingAuthority(trader, signer) {
 		return orderId, hu.ErrNoTradingAuthority
 	}
+	timeTracker = hu.LogTimeTaken("step 3.5", timeTracker)
 
 	requiredMargin := big.NewInt(0)
 	if !order.ReduceOnly {
 		// P2. Margin is available for non-reduce only orders
 		minAllowableMargin := api.configService.getMinAllowableMargin()
+		timeTracker = hu.LogTimeTaken("step 3.6", timeTracker)
 		// even tho order might be matched at a different price, we reserve margin at the price the order was placed at to keep it simple
 		requiredMargin = hu.GetRequiredMargin(order.Price, hu.Abs(order.BaseAssetQuantity), minAllowableMargin, big.NewInt(0))
+		timeTracker = hu.LogTimeTaken("step 3.7", timeTracker)
 		if fields.AvailableMargin.Cmp(requiredMargin) == -1 {
 			return orderId, hu.ErrInsufficientMargin
 		}
@@ -372,6 +384,7 @@ func (api *TradingAPI) PlaceOrder(order *hu.SignedOrder) (common.Hash, error) {
 	if !api.configService.HasReferrer(order.Trader) {
 		return orderId, hu.ErrNoReferrer
 	}
+	timeTracker = hu.LogTimeTaken("step 3.8", timeTracker)
 
 	// validations passed, add to db
 	signedOrder := &Order{
@@ -388,8 +401,11 @@ func (api *TradingAPI) PlaceOrder(order *hu.SignedOrder) (common.Hash, error) {
 		RawOrder:                order,
 		OrderType:               Signed,
 	}
+	timeTracker = hu.LogTimeTaken("step 3.9", timeTracker)
 	placeSignedOrderCounter.Inc(1)
+	timeTracker = hu.LogTimeTaken("step 3.10", timeTracker)
 	api.db.AddSignedOrder(signedOrder, requiredMargin)
+	timeTracker = hu.LogTimeTaken("step 3.11", timeTracker)
 
 	// send to trader feed - both for head and accepted block
 	go func() {
@@ -416,6 +432,6 @@ func (api *TradingAPI) PlaceOrder(order *hu.SignedOrder) (common.Hash, error) {
 		traderEvent.BlockStatus = ConfirmationLevelAccepted
 		traderFeed.Send(traderEvent)
 	}()
-
+	timeTracker = hu.LogTimeTaken("step 3.12", timeTracker)
 	return orderId, nil
 }