From f0fd74bc48d10f5b04208c8fd227e8169436be0d Mon Sep 17 00:00:00 2001 From: atvanguard <3612498+atvanguard@users.noreply.github.com> Date: Fri, 19 Jan 2024 10:54:54 +0000 Subject: [PATCH] log time elapsed --- plugin/evm/order_api.go | 21 ++++++++++++++++--- .../evm/orderbook/hubbleutils/margin_math.go | 11 ++++++++++ plugin/evm/orderbook/trading_apis.go | 18 +++++++++++++++- 3 files changed, 46 insertions(+), 4 deletions(-) diff --git a/plugin/evm/order_api.go b/plugin/evm/order_api.go index dda6ac6239..495236ce49 100644 --- a/plugin/evm/order_api.go +++ b/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 } diff --git a/plugin/evm/orderbook/hubbleutils/margin_math.go b/plugin/evm/orderbook/hubbleutils/margin_math.go index 042d6860cc..5e3b69bf9e 100644 --- a/plugin/evm/orderbook/hubbleutils/margin_math.go +++ b/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 +} diff --git a/plugin/evm/orderbook/trading_apis.go b/plugin/evm/orderbook/trading_apis.go index 1185d6dcc5..c16093b5aa 100644 --- a/plugin/evm/orderbook/trading_apis.go +++ b/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 }